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.

When redo is involved in a performance issue, as shown in Figure 8-11, it is common to see multiple redo-related wait events. Focus on the top event, and then work your way down, while considering expected performance improvement, ease of solution implementation, supportability, and so on. For example, while log file parallel write is the top wait event, simply increasing the redo log buffer size will eliminate most of the log buffer space waits. To make a shockingly strong case for redo problems, by classifying all redo-related waits, you can say that over 99% of all the wait time is associated with redo!