If you start telling people write calls are taking over 200 ms, you're asking for a fight, so be prepared. Even if you are correct, you should expect to be aggressively challenged. So make sure you trace the log writer background process in summary, as shown in Figure 8-13, and in detail, as shown in Figure 8-10. Figure 8-10 highlights the log writer background process is issuing 1MB write calls, Oracle is gathering its timing information from the gettimeofday call and also gathering log writer background process CPU consumption details from the times call. If you run an IO subsystem-focused command, such as iostat, its numbers could be significantly different based on IO caching and physical configuration. So focus on how long it takes the Oracle log writer background process to have its writes serviced.

Figure 8-12. Shown is a v$event_histogram view, allowing us to glean more than the average wait time. For example, we can say that only 3.3% of all the log writer background process writes completed in 8 ms or less. Even more shocking, only 12% of log writer writes completed in less than 16 ms or less.

Figure 8-13 also shows that over the 60-second trace, the log writer made 18 getrusage calls. Back in Chapter 5, I explained that Oracle's system time model, introduced with Oracle Database 10g (v$sess_time_model and v$sys_time_model), gathers Oracle process CPU consumption by having the processes ask the operating system for their process's CPU consumption through a getrusage call, and then places that information into Oracle internal structures. As performance specialists, we can see this CPU consumption via the system time model views. Oracle states the CPU time will be accurate within 5 seconds; my tests have shown the actual time to be typically just over 6 seconds. In the 60-second interval shown in Figure 8-13, since the log writer background process made 18 getrusage calls, the log writer background process CPU consumption information should be accurate to within around 3.3 seconds.