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.

Figure 8-13. Shown is a 60-second interval operating system summary trace of the log writer background process. Within the 60-second interval, Oracle issued 680 write calls (pwrite64), nearly 3,000 gettimeofday calls, and over 2,200 times calls. During this interval, the average write call reported from this operating system utility was 925 ms!