Suppose your analysis clearly shows the IO subsystem takes on average 783 ms to respond to Oracle multiblock read requests. You show this to your IO subsystem vendor, who laughs and then says something like, "First of all, that's what Oracle is telling you, which is false. And second, if you had the tools we have, you would see that our IO subsystem is performing within normal parameters." If you've been working with large Oracle systems, you've probably run into this situation. It can be extremely frustrating.

Fortunately, we can easily remove Oracle from the equation and prove, based on what the operating system is telling us, that the IO subsystem truly is responding to multiple blocks in 783 ms! Figure 4-21 is the result of simply operating system tracing-in this case, tracing an Oracle server process. Using strace with the options -cp suppresses output until you interrupt the trace, and then it produces a very nice summary of the system calls, the occurrences, and their time.

Clearly, the readv call, which occurred nearly 105,000 times (not a bad sample size) during this sample interval, took an average of 783 ms. The pread64 call took only 2.1 ms and occurred nearly 22,000 times. By referring to the manual page for each call and also looking at detailed trace output (for example: strace -rp 28227 >out.out 2>&1), you can see that Oracle uses the readv call for multiblock reads and the pread64 call for single-block reads. These read requests are for blocks outside Oracle's cache. Oracle knows only the blocks' addresses and that they reside outside the buffer cache. It has no idea how the operating system retrieves the blocks. But fortunately for us, through operating system tracing the server process, we can confidently demonstrate that, indeed, Oracle must wait nearly three-quarters of a second for a multiblock read to complete.