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.

Now I realize this will not improve relationships with IO vendors, but it does put them on the defensive, and forces them to take a good, long look at what the IO subsystem is really doing!