Topic: This post is about tracing logical and physical reads in Oracle using SystemTap. You find here a few examples illustrating the main mechanisms used by Oracle to performo physical and logical I/O and you learn how to build SystemTap scripts to further explore and troubleshoot Oracle I/O.

Introduction: Performing input/output from and to the storage media, i.e. physical I/O, is one of the critical tasks underlying all database engines. When accessing data stored in RAM from the database cache we can talk of logical I/O. Physical I/O is performed by the database using system calls to the O/S kernel. The type of system calls used depends on database settings, the O/S and the type of storage. Logical I/O is performed by the database processes using Oracle kernel functions. Oracle instruments the timing of physical I/O calls with the wait event interface, while logical I/O time is generically accounted for as CPU time. Tracing I/O operations performed by Oracle processes together with the details provided by the Oracle wait event interface is a powerful technique to investigate Oracle I/O internals. With the help of a few real-life examples we investigate what the mechanisms are that Oracle uses to access storage, how the I/O operations correlate to the wait event interface and what the meaning of the wait event time is for the most common wait events associated with I/O.

Tracing physical I/O: Oracle ultimately issues system calls to execute I/O operations. The type of calls depend on database settings, the O/S type and the type of storage. In this article you can find examples to Oracle on Linux using ASM storage on block devices. Notably direct NFS, local storage and ASM with asmlib are left out and possibly addressed in future studies. System calls can be traced using the strace(1) utility in Linux too. However, in this article you can see how SystemTap probes can be built to gather information on the system calls of interest: pread, pwrite, io_submit and io_getevents. Additional useful SystemTap probes to the underlying block I/O layer are: ioblock.request, ioblock_trace.request and ioblock.end (note, these are not system calls, but rather tracepoints for function calls inside the Linux kernel).

Note added, August 2015: Systemtap probes on kernel.trace("block_rq_issue") and kernel.trace("block_rq_complete") can also be used to investigate the block I/O interface with the added advantage of not requiring kernel debuginfo. You can find examples of such probes in the page with download material or on GitHub.

Tracing logical I/O: This is about providing the history and details of the logical I/O operations, which is when Oracle reads a data block from memory (buffer cache). Logical I/O operations are a super-set of physical I/O: if Oracle does not find data in memory (buffer cache) it will issue a physical read. You can find a few examples of this mechanism in action later in this post.

Oracle instrumentation provides extensive information on logical reads in several V$ views, such as V$SYSSTAT, V$SESSTAT, V$SYSMETRIC. Also logical read data is available from sql*plus with "set autotrace on" and with tkprof reports of 10046 traces. Logical reads come in two main "flavors": consistent reads and current reads. Oracle will use consistent reads when reading data at a given system change number SCN, current reads are used when performing DML operations on the block. Consistent reads can be traced in Oracle using the events 10200 and 10201. More details can be found in the presentation by Julian Dyke on logical I/O.

In this article we show how to trace logical I/O by attaching SystemTap probes to a set of Oracle kernel functions. The role of functions kcbgtcr and kcbgcur for tracing consistent and current reads has already been discussed by Alexander Anokhin in his excellent blog articles on Dtrace LIO. More recently I have investigated this topic and found useful to also trace the functions kcbzib, kcbzgb, kcbzvb.

A summary of the main finding on these functions is in the table here below. Note: the expressions %rdi, %rsi, %r8 indicate the values of the corresponding CPU registers. With SystemTap the register value can be read with the function register, example: register("rdi"). The CPU registers are used to extract the function call arguments. Systemtap does not provide the function call arguments when there are no debug symbols available for the executable. Notably the calling conventions for x86-64 as documented in  www.x86-64.org/documentation/abi.pdf state that the integer parameters for a function call are available in the following registers (in order): %rdi, %rsi, %rdx, %rcx, %r8 and %r9.

Note: as I write this only uprobes for kernel versions 3.10 or higher support return probes for userspace functions. Therefore this functionality is not available with RHEL or OL 6.x, but it is available on RHEL 7.x kernels.

Tracing wait events: The wait event interface is probably one of the best features in Oracle performance tuning as it provides a quantitative method to identify performance issues and bottlenecks. Cary Millsap has published inspiring work on the subject.

For our purposes it suffices to say that wait events are instrumentation points where selected Oracle kernel actions are timed. In particular Oracle will time the start and end calls to most physical I/O operations, therefore providing a good way to understand how much time is spent during physical I/O (some limitations of this mechanism are discussed later in this post). There are also limitations to using the wait event interface to study I/O latency, in particular in the examples section you can find some interesting challenges related to timing asynchronous I/O events.

Wait event tracing is typically activated in Oracle using the 10046 event or with by calling DBMS_MONITOR.SESSION_TRACE_ENABLE. In this article we get the wait event details by attaching SystemTap probes to the relevant Oracle kernel functions and in particular to  kskthbwt and kskthewt to gather information respectively at the start and at the end of each wait event. Enabling wait event tracing using event 10046 at level 8 and other methods is a way to externalize the wait event timing information (as well as other SQL processing details), not to enable the wait information. This is done using the database parameter TIMED_STATISTICS, and is and should be set to TRUE in modern Oracle databases. One key piece of information that the Oracle kernel functions kskthbwt and kskthewt give us is a pointer into the X$KSUSE fixed table (or rather to the underlying memory structure in the SGA), which is the underlying table to V$SESSION and therefore opens the road to correlate the wait event with many useful information on session executing the SQL. Resolving the pointer in register r13 to the base value of X$KSUSE and computing the offset for the fields of interest requires additional work, this is described in a previous article (see also the script: ksuse_find_offsets.sql).

This example is about single block (random) reads. This access path to data is very important for many OLTP workloads as it is used for table access via a index key. In Figure 1 here below you can see a snippet of a trace file for a query of the type: select <col_list> from table <tab> where <indexed_col>=<val>.

The key points are:

• Oracle issues a logical read on one of the blocks needed to to retrieve data for the SQL of this example
  • additional details are provided in the logical read call where we can see that Oracle wants to read block#=2505675 from tbs#=7 and belonging to obj#=32174 (which is the table segment in this example)
• The block is not found the cache so a new block is allocated in the buffer cache and a physical read is initiated
• The database marks the start of a wait event for 'db file sequential read'
• The physical read request for a block becomes a pread call to the O/S
  • The IO request enters the kernel via a system call, any function encountered after the system call is a kernel function (such as ioblock.request), until the system call returns, and thus gets back to userland, which means the Oracle executable in this case.
• This read call is passed on to the block I/O interface to read 8192 bytes (1 database block), from the block device device (/dev/sdl in the example of Figure 1)
• The block interface and then the OS call return the read data to the Oracle kernel
• The Oracle wait interface marks the end of the wait and computes the elapsed time
  • the wait event is  'db file sequential read' and the parameters are: p1 is the file number, p2 in the block number, p3 is the number of blocks read (1 block).
  • from the timestamp values in the trace you can see that the duration of the db file sequential read wait is dominated by the time it took to do the pread call, with a small overhead (note also that the overhead could have been more significant if we had high CPU utilization on the DB server, for example because of workload from other Oracle sessions)
• We can conclude that in this example the measured wait time for db file sequential read corresponds to physical read latency.

Example 2: sequential I/O into the buffer cache with synchronous I/O

This example is about multi-block reads into the cache. This is an access path that is used for example when Oracle performs a full table scan. There are multiple ways in which Oracle can access the storage to perform full scans, in this example you see the case when Oracle uses synchronous I/O (i.e. the pread call) to perform O/S reads, examples 3 and 4 cover sequential reads with asynchronous I/O. In Figure 2 here below you can see a snippet from tracing the workload of a query of the type: select <col_list> from table <tab>, a full scan of <tab> is performed by Oracle.

The key points of the trace in Figure 2:

• Oracle issues a consistent read for tbs#=7 block#=2621443 and finds it in the cache
• Oracle issues a consistent read for the next block, does not find it in the cache so prepares to read a list of block from storage in one physical read. The list is 124-blocks long (it has shortened in this example for clarity)
• The databases marks the start of a wait event for "db file scattered read"
• The physical read requests become a single pread call to the OS for 1015808 bytes (124 blocks)
• This request moves down the I/O chain to the block I/O interfaces which splits it into 2 reads from the underlying block device, as in the system used for tests the maximum size of I/O is 524288 bytes.
  • As investigated by Frits Hoogland: the submitted I/O request lands in the IO scheduler scattered/gather list, where it is broken down to the IO size as advertised by the block device.
• The I/Os are completed by the block I/O interface
• The pread call returns
• The wait event interface times the end of the wait
  • The wait event is db file scattered read and the parameters are: p1 is the file number, p2 in the block number, p3 is the number of blocks.
  • From the timestamp values in the trace you can see that the duration of the db file scattered read wait is mostly accounted for by the time it took to do the pread call, with a small overhead 
• From the trace of calls to the Oracle kernel function kcbzvb we get additional confirmation of the blocks that have been read
• We can conclude that in this example the wait time for db file scattered read corresponds to I/O latency.

Example 3: sequential I/O into the buffer cache with asynchronous I/O O/S calls

In Figure 3 you can see a snippet from the trace of  the SQL: select <col_list> from table <tab>, where Oracle performs a full scan of table <tab>. This is the same query that was used for Example 2 above, the difference from that case is that the trace in Figure 3 has been taken at a later time in the execution of the query, when the Oracle process switched from using synchronous I/O with pread calls to using the asynchronous  I/O interface. Asynchronous I/O is implemented in Linux with io_submit and io_getevents calls, to send the I/O requests and then to reap the results. Although Oracle uses the asynchronous interface to perform read operations in this example, the final result is very similar to what described in Example 2 (i.e. with synchronous I/O): the Oracle wait event is the same, "db file scattered read", the reads are also performed into the buffer cache and I/Os are reaped with blocking calls, therefore making the process effectively synchronous. A more 'aggressive use' of the asynchronous I/O interface by Oracle aimed is found in Oracle with direct reads, that are discussed in Example 4 below.

The key points are:

• Oracle issues a consistent read for tbs#=7 block#=2522760, it does not find it in the cache so prepares to read a list of blocks into the buffer cache. The list is 128-blocks long and shortened in this example
• The databases marks the start of a wait event for "db file scattered read"
• The physical read requests are passed on to the OS as a call to io_submit with 2 requests for a total of 1MB in size (that is 128 blocks): the first request is for a read (opcode 0) of 65536 bytes, the second for a read operation of 983040 bytes (that is 1MB -64 KB)
• These requests are passed to the block I/O interface which splits the largest request into 2 reads from the underlying block device (/dev/sdi in this example). The read of 64KB is passed on unchanged in size to /dev/sdr
• Oracle calls io_getevents to reap the results of the asynchronous I/O requests that have just been submitted and waits. The timeout.tv_sec field is set to 600, which indicates this is a blocking wait (which means io_getevents waits for 600 secs (tv_sec) and 0 nano secs (tv_nsec)) for min_nr=2 of IOs to finish. 
• The block device interface returns the data upstream.
• The io_getevents call returns the 2 I/O read.
• The wait event interface marks the end of the wait. The wait event in this case is db file scattered read. 
  • The wait event parameters are: p1 is the file number, p2 in the block number, p3 is the number of blocks.
  • The wait event duration is basically the time is took to do the io_submit and io_getevents calls plus a small overhead.
  • Note that although Oracle has used the asynchronous interface, it has also waited for all the I/Os to complete therefore making the I/O essentially synchronous
• From the calls to kcbzvb we get additional confirmation of the blocks that have been read.
• Conclusion: the wait time for db file scattered read in this example is not a precise measure of the I/O latency, as two reads on two different devices where submitted in parallel and the total time was reported as if it was a single read.

Example 4: full scans with direct reads and asynchronous I/O

In this paragraph you can find two examples of Oracle I/O for the case of direct reads on block storage configured with ASM. The same query that was used in Examples 2 and 3 above is also used here: it is a query that performs a full table scan. In this example differently from Examples 2 and 3 Oracle uses serial direct read to access data. Serial direct read is a feature introduced in 11gR2 for optimizing full segment scan operations and bypassing the buffer cache layer, similarly to what happens with parallel queries. Oracle chooses when to use serial direct reads vs. cached reads based on a few parameters. In first approximation direct reads are preferred when the table is "big" compared to the size of buffer cache, the actual mechanism is more complex and can potentially change between Oracle versions. You can read more on this topic in this blog post by Tanel Poder.

For the particular setup I used to run this tests I had to force the use of serial direct reads before running the query, this was done with: alter session set "_serial_direct_read"=always; 

Note that alter session set "_serial_direct_read"=never; can be used to disable serial direct reads and force Oracle to use cached reads (that is the type of I/O you have seen in Example 2 and 3 above). The default value for the underscore parameter "_serial_direct_read" is "auto".

For the investigations in this example we can use a slightly different SystemTap probe from what we have used in the previous examples. I have removed tracing of logical I/O and block I/O for reducing cluttering and added a new probe on the userspace function io_getevents_0_4 of libaio (libaio is the Linux library that implements asynchronous I/O). This is because serial direct reads use non-blocking calls to reap I/Os and these calls are best traced at the libaio interface for reasons described by Frits Hoogland in this blog post. The SystemTap script represented in Figure 4a and 4b is: trace_oracle_wait_events_asyncio_libaio_12102.stp (a version for 11.2.0.4 is available at trace_oracle_wait_events_asyncio_libaio_11204.stp).

The key points of Figure 4a are:

• Oracle requests I/O in chunks of contiguous storage space of 1MB. This is to reduce the overhead of seek time and potentially make use of readahead when available. 
  • The value of 1MB for the read request comes from the parameter db_file_multiblock_read_count=128 multiplied by the block size of 8 KB. 
• Oracle submits one I/O of 1 MB with a call to io_submit and then calls io_getevents_0_4 in the libiao library using the non-blocking mode to try to reap the I/O. This happens twice, with no results. Oracle then submits another I/O of 1MB and tries for 4 times to reap I/O in non-blocking mode, with no results (the I/O operations have not yet finished).
• The wait event timing starts just before the calls to io_getevents, which are used to reap the I/O results this time in blocking mode (with a timeout of 600 seconds)
  • The wait event in this case is: "direct path read"
  • Oracle reaps the two I/Os in two subsequent calls to io_getevents
• After reaping the I/Os Oracle marks the end of wait for the event. 
• The result is that 2 reads of 1 MB each have been performed 
• The wait event interface does not report the correct number of I/Os performed:
  • the "direct path read" wait in this example reports one read of 128 blocks (1 MB), while 2 MB were read
• The elapsed time for the wait event "direct path read" does not measure the I/O latency
  • Oracle is only timing the blocking calls to io_getevents, which start after the I/Os are submitted. 
  • Oracle is timing 2 reads together.

The use of serial direct reads in Oracle is more complex than the simple example of Figure 4a. Frits Hoogland has discussed this in more details the internals of direct reads in Oracle in this presentation. In particular Oracle uses an adaptive mechanism for direct reads with the goal of driving the storage system to high throughput when possible. This is implemented by increasing the number of outstanding I/O when calling the asynchronous I/O interface. Internally this makes use of I/O slots. Note, from a comment on Oracle diagnostic event 10353 we have additional indirect information on this topic: "Slots are a unit of I/O and this factor controls the number of outstanding I/Os".