When you find that IO response times are only a couple of milliseconds or less, remember that it takes CPU resources to satisfy these IO requests. It is very common for a seemingly IO-bottlenecked system to actually be suffering from a CPU bottleneck. Performing an OraPub 3-circle analysis and the associated ORTA will clearly show this, so there should be no surprises.

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.