|
|
|
|
Introduction
In early 2002 Roger Schrag published a paper entitled, "Interpreting Wait Events to Boost System Performance." That paper began with a definition of wait events and techniques for collecting wait event information, and then went on to discuss four examples of how wait event data had been used to solve real-life performance problems. The impetus for writing that paper had been that, while many resources were available that listed the wait event v$ views, we were not aware of any publication that actually explained how to use the wait event interface to solve problems or boost system performance.
As we write this paper in early 2003, we still are not aware of any such publications. Now Roger Schrag has teamed up with fellow Oracle DBA Terry Sutton to document more examples of how Oracle's wait event interface can be used to solve real-world problems. In essence, this paper is a sequel to last year's paper. If you haven't read the first one, you may view it at http://www.dbspecialists.com/presentations.html. You can read the two papers in either order.
In the first two parts of this paper, we will once again define what wait events are and how to collect wait event information. If you have read the previous paper or are already familiar with the wait event interface, we still encourage you to read these sections as we've added some enhancements and new details regarding Oracle 9i. In the third part of this paper we'll move on to new examples of how wait event information paved the way to solving real-world performance problems. Our feeling is that the more examples of wait event usage you are exposed to, the better position you'll be in to put the wait event interface to work for you when you most need it.
What are Wait Events?
The wait event interface appeared in the first production release of Oracle 7. For many years it remained undocumented, and few people outside the kernel group at Oracle Corporation knew of its existence. By Oracle 7.3 the word was out, and the documentation that comes with Oracle 8.0 and later gives a pretty good explanation of the wait event interface. In Oracle 9i, wait event tracing has been made much easier with the inclusion of the DBMS_SUPPORT package in the kernel, and with the new wait events reporting feature of TKPROF.
The basic idea behind the wait event interface hasn't changed since its inception, but Oracle continues to add new wait events as they add new functionality to the Oracle kernel. Also, newer enhancements make the wait event interface easier to use.
In this section we will explain what wait events are and why the data provided by the wait event interface can be helpful.
"Wait Event" Defined
At any given moment, every Oracle process is either busy servicing a request or waiting for something specific to happen. By "busy" we mean that the process wishes to use the CPU. For example, a dedicated server process might be searching the buffer cache to see if a certain data block is in memory. This process would be said to be busy and not waiting. The ARC0 process, meanwhile, might be waiting for LGWR to signal that an online redo log needs archiving. In this case, the ARC0 process is waiting.
The kernel developers at Oracle have defined a list of every possible event that an Oracle process could be waiting for. In Oracle 8.0 there were 158 such wait events. In Oracle 9i Release 2 there are 363. At any moment, every Oracle process that is not busy is waiting for one of these events to occur. Suppose an application has submitted a COMMIT statement and the server process is waiting for the LGWR process to signal that the redo log buffer has been flushed to disk. This wait event is called "log file sync." Another dedicated server process might be waiting for a row-level lock on the INVOICES table to be freed so that a SELECT FOR UPDATE statement can continue. That wait event is called "enqueue."
It is very beneficial that Oracle is diligent about tracking wait event information and making it available to DBAs. We call this the "wait event interface." By querying v$ views, we can see what events processes are waiting on to an amazing level of detail. For example, we might learn that a dedicated server process has been waiting 30 milliseconds for the operating system to read eight blocks from data file 42, starting at block 18042. We can also see summary information of how much time each Oracle process has spent waiting on each type of wait event for the duration of the process. In addition, we can direct an Oracle process to write detailed wait event data to a trace file for later analysis using TKPROF.
Why Wait Event Information is Useful
Using the wait event interface, you can get insights into where time is being spent. If a report takes four hours to complete, for example, the wait event interface will tell you how much of that four hours was spent waiting for disk reads caused by full table scans, disk reads caused by index lookups, latch contention, and so on.
The wait event interface provides much more information to work with than cache hit ratios do. The wait event interface gives both breadth and depth in the information it provides. You get data that can touch upon so many different areas of your database such as disk I/O, latches, parallel processing, network traffic, checkpoints, and row-level locking. At the same time, you get incredible detail such as the file number and block number of a block being read from disk, or the name of a latch being waited on along with the number of retries.
The wait event interface will not always give you all of the information you need in order to diagnose and solve a problem, but it will certainly point you in the right direction. You might think the buffer cache is too small because the cache hit ratio is only 70%, but in fact, the application's slow response time could be caused by latch contention in the shared pool, a bottleneck in the log writer, or any of a number of other things.
Common Wait Event Names and What They Mean
Although there are many different types of wait events, the majority of them come up very infrequently or tend not to be significant. In practice, only a few dozen wait events tend to be of interest to most DBAs. The rest are rather obscure, pertain to Oracle features not in use, or occur so infrequently that you don't need to worry about them. You'll see different wait events surfacing in different environments based on which Oracle features have been implemented and which capabilities of the database are being taxed the most.
For example, the PX wait events won't appear if you aren't using parallel query, and the virtual circuit status wait event won't appear if you are not using the multi-threaded server architecture (or shared server architecture as it is more recently called). Along those lines, the log file sync and enqueue wait events probably won't be prevalent in a primarily read-only system.
Here are some of the most common wait events and what they mean:
| Wait Event | Description |
| buffer busy waits | The session wants to access a data block that is either 1) currently not in memory, but another process has already issued an I/O request to read the block into memory, or 2) in memory but in an incompatible mode (current versus consistent, for example). |
| control file parallel write | The session has issued multiple I/O requests in parallel to write blocks to all control files, and is waiting for all of the writes to complete. |
| control file sequential read | The session is waiting for blocks to be read from a control file. |
| db file parallel read | The session has issued multiple I/O requests in parallel to read blocks from data files into memory and is waiting for all requests to complete. This may occur during recovery or during regular activity when a session batches many single block I/O requests together and issues them in parallel. |
| db file parallel write | The process, typically DBWR, has issued multiple I/O requests in parallel to write dirty blocks from the buffer cache to disk and is waiting for all requests to complete. |
| db file scattered read | The session has issued an I/O request to read a series of contiguous blocks from a data file into the buffer cache and is waiting for the operation to complete. This typically happens during a full table scan or fast full index scan. |
| db file sequential read | The session has issued an I/O request to read one block from a data file into the buffer cache and is waiting for the operation to complete. This typically happens during an index lookup or a fetch from a table by ROWID when the required data block is not already in memory. |
| direct path read, direct path write |
The session has issued asynchronous I/O requests that bypass the buffer cache and is waiting for them to complete. These wait events often involve temporary segments. |
| enqueue | The session is waiting on an enqueue (a lock you can see in v$lock). This commonly occurs when one user is trying to update a row in a table that is currently being updated by another user. |
| free buffer waits | The session needs a free buffer so it can bring a data block into the buffer cache and is waiting for a buffer that is not dirty to become available. This can occur if DBWR is not writing dirty buffers to disk fast enough. |
| latch free | The session is waiting for a latch held by another session. (This event does not apply to processes that are spinning while waiting for a latch; when a process is spinning, it is not waiting.) |
| library cache load lock | The session is waiting for the opportunity to load an object or a piece of an object into the library cache. (Only one process can load an object or a piece of an object at a time.) |
| library cache pin | The session wants to pin an object in memory in the library cache for examination, ensuring no other processes can update the object at the same time. This happens when you are compiling or parsing a PL/SQL object or a view. |
| log buffer space | The session is waiting for space in the log buffer. (Space becomes available only after LGWR has written the current contents of the log buffer to disk.) This typically happens when applications generate redo faster than LGWR can write it to disk. |
| log file parallel write | The session is waiting for blocks to be written to all online redo log members in one group. LGWR is typically the only process to see this wait event. It will wait until all blocks have been written to all members. |
| log file sequential read | The session is waiting for blocks to be read from the online redo log into memory. This primarily occurs at instance startup and when the ARCH process archives filled online redo logs. |
| log file switch completion | The session is waiting for a log file switch to complete, typically so more redo can be generated. |
| log file sync | The session is waiting for LGWR to finish flushing the log buffer to disk. This occurs when a user commits a transaction. (A transaction is not considered committed until all of the redo to recover the transaction has been successfully written to disk.) |
| undo segment extension | The session is waiting for an undo segment to be extended or shrunk. |
| write complete waits | The session is waiting for a requested buffer to be written to disk; the buffer cannot be used while it is being written. |
There are several wait events that we call "idle events" because each of these wait events typically occurs when the Oracle process has nothing to do and is waiting for somebody to give it a task. Idle events are usually not very interesting from a tuning standpoint, so we usually overlook them when evaluating data extracted from the wait event interface. The common idle events are as follows:
| client message | PX Deq: Execute Reply |
| dispatcher timer | PX Deq: Execution Msg |
| gcs for action | PX Deq: Signal ACK |
| gcs remote message | PX Deq: Table Q Normal |
| ges remote message | PX Deque wait |
| i/o slave wait | PX Idle Wait |
| jobq slave wait | queue messages |
| lock manager wait for remote message | rdbms ipc message |
| null event | slave wait |
| parallel query dequeue | smon timer |
| pipe get | SQL*Net message from client |
| PL/SQL lock timer | SQL*Net message to client |
| pmon timer | SQL*Net more data from client |
| PX Deq Credit: need buffer | virtual circuit status |
| PX Deq Credit: send blkd | wakeup time manager |
What Wait Event Information Does Not Provide
If an Oracle process has work to do but must wait for something to happen before it can continue, then the process will be waiting on a non-idle wait event. If a process has nothing to do, it will be waiting on an idle wait event. So what happens if a process has work to do and is busy doing it? When a process is busy, there will be no information in the wait event interface since the process is not waiting.
When we look at the wait event information extracted from an Oracle instance, we see detailed information about how many times and how much time was spent waiting for specific events to occur. But we do not see anything about the time periods in which the process requested use of the CPU. This means that the wait event interface is not able to provide information about the following:
This is important to keep in mind because there is an easy trap to fall into. You could be troubleshooting a very slow SELECT statement and learn from the wait event interface that the process does not have significant wait events when running the query. This could lead you to think that the statement is optimal, and that it just takes a long time to run. In fact, however, the query might be performing huge numbers of logical reads and the number of buffer gets could be reduced by rewriting the query.
When Oracle needs to access a data block and the block is already in the buffer cache, a logical read occurs with no physical read. The process is able to read the block without the occurrence of any wait events. Large amounts of CPU time could be consumed on significant numbers of logical reads, and the wait event interface will have nothing to show for the elapsed time.
Statement parsing and spinning while waiting for a latch to become available are two other examples of activities not accounted for by the wait event interface. An Oracle process uses CPU time while parsing a statement or spinning on a busy latch; since no waiting is involved, the wait event interface does not have anything to report.
Oracle Corporation has done something interesting with Statspack recently. Beginning in Oracle 9i, the portion of the Statspack report that lists wait event information also lists CPU usage. This is very helpful information. It allows us to easily compare time spent waiting to time spent processing, so we know where to focus our tuning efforts. However, it should be pointed out that the CPU usage information in this section of the Statspack report does not come from the wait event interface. Instead, Statspack merges data collected from the wait event interface with CPU usage information collected from the v$sysstat dynamic performance view.
A Note About the timed_statistics Parameter
The Oracle kernel is capable of timing many activities including wait events. In Oracle 8i and earlier, timed statistics can be tracked to a resolution of one centisecond (0.01 second) but are disabled by default. Beginning in Oracle 9i Release 2 timed statistics are collected by default, and some timings are collected in units of microseconds. The timed_statistics instance parameter is used to enable and disable timed statistics collection. When timed_statistics is set to FALSE, all times in the wait event interface will appear as zero. You may enable timed statistics collection at the instance or the session level with the following commands:
ALTER SYSTEM SET timed_statistics = TRUE;
ALTER SESSION SET timed_statistics = TRUE;
You may enable timed statistics at the instance level on the next and all subsequent instance restarts by adding the following line to the instance parameter file:
timed_statistics = true
In practice, the overhead of collecting timed statistics is extremely small. In most cases, the benefit you'll get from having timing information at your disposal will outweigh the performance overhead. For several years, many DBAs have been running their production systems with timed statistics enabled at all times. With Oracle 9i Release 2, this is now the default behavior.
