Figure 8-10. Shown is an operating system trace of a very busy log writer on a Linux Oracle Database 10g Release 2 system. Notice the gettimeofday calls are not tightly wrapped around each write call, reducing the gettimeofday call overhead. While not apparent in this snippet, the majority of write calls are 1MB.

The trace file snippet in Figure 8-10 is not what performance analysts like to see. The first write call took 1.3 seconds to complete, followed by 43.4 ms, 33.6 ms, and finally 116.3 ms. Obviously Oracle's IO requirements have exceeded the IO subsystem's capacity. If you see a trace file like this, you are highly likely to see the log file parallel write as your top wait event.

Figure 8-10 also shows that log writer background process calls on this Linux Oracle Database 10g Release 2 system are not tightly wrapped within a gettimeofday call. While this might initially be a little unsettling, making you think Oracle's timing may now be in error, as long as Oracle also knows the number of writes and also the multiple write call duration, it can easily calculate the average. In fact, reducing the number of gettimeofday calls when the process makes quick multiple write calls (as occurred in Figure 8-10) is not only more efficient, but also shows Oracle is making efforts to reduce its kernel code instrumentation overhead.