Wait Event Enhancements in Oracle 10g
Wait Event Enhancements in Oracle 10gby Terry Sutton and Roger Schrag
Database Specialists, Inc.
About Database Specialists, Inc.
Database Specialists, Inc. provides remote DBA services and onsite database support for your mission critical Oracle systems. Since 1995, we have been providing Oracle database consulting in Solaris, HP-UX, Linux, AIX, and Windows environments. We are DBAs, speakers, educators, and authors. Our team is continually recognized by Oracle, at national conferences and by leading trade publications.
Learn more about our
, and& services. Or, call us at 415-344-0500 or 888-648-0500.
Introduction
The wait event interface has continued to be an invaluable tool for DBAs as it offers both breadth and depth in the information it provides to aid in troubleshooting and boosting system performance. Throughout this paper we will assume the reader is familiar with wait event concepts and the wait event interface in Oracle. In particular, this paper is designed for DBAs who have experience using the wait event facility in Oracle 9i or earlier and want to learn what enhancements have been made in Oracle 10g. (Those new to this area of Oracle technology might want to first read our paper entitled, “Interpreting Wait Events to Boost System Performance” available for free download at .)
There are still significant gaps in the documentation as of Oracle 10g release 10.1.0.3, making it that much harder to learn what has changed in Oracle 10g with respect to wait events and the wait event interface. For example, the Oracle 10g Database Reference manual (part number B10755-01) still provides the wait events list from Oracle 9i. For this reason, you might find the
listed at the end of this paper to be useful. It lists all of the wait event names for Oracle 10g release 10.1.0.3, along with the parameter names for each.
Although introduced in Oracle 7, not much changed in the wait event interface through and including Oracle 9i.
Oracle 7.3 had just 106 wait events, while that number has increased to over 400 in Oracle 9i. Also, Oracle 9i TKPROF reports include wait event information and Oracle 9i v$ views show wait times in microseconds. But these are minor enhancements, really. Oracle 10g, on the other hand, brings more significant change to the wait event interface than we have seen in years. Now there are over 800 wait events and names are more descriptive, wait events are categorized into classes, several v$ views have been added, helpful columns have been added to existing v$ views, built-in statistics collection by Active Session History and the Automatic Workload Repository has been introduced, a new time model concept for looking at how sessions spend their time has appeared, and improvements have been made to the session tracing facility.
Wait Event Enhancements in Oracle 10g
In this section, we will introduce what we see as the top dozen areas in which wait events and the wait event interface have been enhanced in Oracle 10g. We’ve listed these enhancements in no particular order.
More Descriptive Wait Event Names
Prior to Oracle 10g, some wait event names were quite vague and not very useful without looking at the parameter values for a specific occurrence of the event. For example, an enqueue wait could indicate various situations ranging from contention for a row in a table to waiting on a user-defined lock. Wait event names in Oracle 10g are more descriptive in the areas of latches, enqueues, and buffer busy waits.
There is still a latch free wait event in Oracle 10g, but there are also 26 more specific latch-related events. These cover the most common latches that experience contention. In the past, if we saw a session waiting on the latch free event, we would have output like the following:
SQL> SELECT event, state, p1, p2, p3
v$session_wait
sid = 162;
------------- ------- -----------
------ -----
latch free
We would then have to query v$event_name to determine the meaning of the parameters p1, p2, and p3:
SQL> SELECT * FROM v$event_name WHERE name = 'latch free';
EVENT# NAME
PARAMETER1
PARAMETER2
PARAMETER3
------ ---------- --------------- --------------- ---------------
3 latch free address
And, seeing that p2 is the latch number, we would need to query v$latch to find out which latch was being waited upon:
SQL> SELECT name
latch# = 97;
--------------------
cache buffers chains
In Oracle 10g we simply see:
SQL> SELECT event, state
v$session_wait
sid = 162;
------------------------------ -------
latch: cache buffers chains
The descriptive event name saves us two steps in determining which latch is causing the wait. The more detailed description enables one to more quickly drill down to the root cause of the wait.
The names of enqueue-related wait events have also been made more descriptive in Oracle 10g. There is no longer an enqueue wait event—it has been replaced by 184 events with more detailed names. In the past, if sessions were waiting on enqueues, we would have to decode the type of lock from the p1 parameter:
SQL> SELECT event, state, seconds_in_wait siw
v$session_wait
----------------------------------- ------------------- ----------
SQL> SELECT sid,
CHR (BITAND (p1,-) / ) ||
CHR (BITAND (p1, ) / 65535) enq,
DECODE (CHR (BITAND (p1,-) / ) ||
CHR (BITAND (p1, ) / 65535),
'TX', 'Transaction (RBS)',
'TM', 'DML Transaction',
'TS', 'Tablespace and Temp Seg',
'TT', 'Temporary Table',
'ST', 'Space Mgt (e.g., uet$, fet$)',
'UL', 'User Defined',
CHR (BITAND (p1,-) / ) ||
CHR (BITAND (p1, ) / 65535)) enqueue_name,
DECODE (BITAND (p1, 65535), 1, 'Null', 2, 'Sub-Share',
3, 'Sub-Exclusive', 4, 'Share', 5, 'Share/Sub-Exclusive',
6, 'Exclusive', 'Other') lock_mode
v$session_wait
ENQUEUE_NAME
----- ---- ------------------------------ ----------
Transaction (RBS)
In Oracle 10g we get more information directly from the enqueue name:
SQL> SELECT event, state, seconds_in_wait siw
v$session_wait
sid = 143;
----------------------------------- ------------------- ----------
enq: TX - row lock contention
Additionally, more information is available in some cases from the p1, p2, and p3 parameters, whose meanings vary with the different enqueue-related wait events. (See the
for a listing of all wait events and their associated parameter meanings.)
In addition to latch and enqueue waits, there are a few other wait events that have more descriptive names in Oracle 10g. However, the state of the Oracle 10g documentation as of this writing makes it hard to enumerate all of them. One example of another descriptive name change has to do with buffer busy waits. The situation where one session is waiting for another session to read in a desired data block from disk (reason code 130) has been given the more descriptive wait event name “read by other session.”
Wait Event Classes
In Oracle 10g wait events are classified into categories which can help the DBA to more easily determine the likely root cause of the wait.
The categories are:
&Administrative&&Idle
&Application&Network
&Cluster&Scheduler
&Commit&System I/O&&&&
&Concurrency&User I/O
&Configuration&Other
While nearly 70% of the wait events are in the “Other” category (557 out of 811 in release 10.1.0.3), the most frequently encountered ones are in wait classes with helpful names. Let’s look at the wait class designations of some enqueue events as an example:
SQL> SELECT
wait_class, name
v$event_name
name LIKE 'enq%'
wait_class &> 'Other'
ORDER BY wait_
WAIT_CLASS
------------------------------ ----------------------------------------
Administrative
enq: TW - contention
Administrative
enq: DB - contention
Application
enq: PW - flush prewarm buffers
Application
enq: RO - contention
Application
enq: RO - fast object reuse
Application
enq: TM - contention
Application
enq: TX - row lock contention
Application
enq: UL - contention
Concurrency
enq: TX - index contention
Configuration
enq: ST - contention
Configuration
enq: TX - allocate ITL entry
Configuration
enq: SQ - contention
Configuration
enq: HW - contention
We see that TX enqueues (row locks) and TM enqueues (table locks) are in the Application class, which makes sense since these wait events generally occur because of application behavior.
Meanwhile, ST (space management), HW (high-water mark extension), and SQ (sequence number) enqueues are in the Configuration class, as these can usually be alleviated by changes in object and database settings.
The User I/O class includes the db file scattered read, db file sequential read, direct path read, and direct path write events as one might expect, while the System I/O class includes many waits related to reading and writing of redo logs and archive logs.
The Commit class has one member, log file sync, as that wait is caused by commits. And the Idle class is made up of various wait events which have traditionally been considered “idle events,” such as SQL*Net message from client. It should be noted that sometimes such “idle events” can actually be symptoms of the root cause of poor performance, so they should not be disregarded without consideration.
In general, the addition of wait classes helps direct the DBA more quickly toward the root cause of performance problems.
v$ View Enhancements
In Oracle 10g there are quite a few new v$ views that pertain to wait events, and helpful new columns have been added to existing v$ views. We will discuss several of the enhancements in this section, although some new v$ views are part of major new Oracle 10g functionality and will be discussed in separate sections later on.
v$event_name
Three columns have been added to the v$event_name view in Oracle 10g: wait_class_id, wait_class#, and wait_class.
These columns show which wait class the wait event is part of. We saw in the previous section how this new information might be used. The columns in v$event_name now are:
SQL> DESCRIBE v$event_name
----------------------------------------- -------- ----------------------------
VARCHAR2(64)
PARAMETER1
VARCHAR2(64)
PARAMETER2
VARCHAR2(64)
PARAMETER3
VARCHAR2(64)
WAIT_CLASS_ID
WAIT_CLASS#
WAIT_CLASS
VARCHAR2(64)
v$sql and v$sqlarea
The v$sql and v$sqlarea views have six new columns in Oracle 10g that relate to wait events:
&application_wait_time&
&concurrency_wait_time&
&cluster_wait_time&
&user_io_wait_time&
&plsql_exec_time&
&java_exec_time&
These columns are designed to identify the amount of time a SQL statement spends in PL/SQL or Java code execution, or waiting in four specific wait classes. The Oracle release 10.1.0.3 documentation provides almost no information concerning these new columns, though they could be extremely important in diagnosing performance problems. In the absence of documentation, we will use an example to demonstrate the behavior and value of these new columns.
Suppose we create a table called testtab with about a million rows. We then run the following statement from one session without committing, and then run the same statement from another session:
SQL> UPDATE testtab SET numcol = numcol + 1 WHERE ROWNUM & 1000;
Obviously the second session will wait on an enqueue wait event until the first session either commits or rolls back. After a while we roll back the first session and then the second session. Next, in a third session, we run the following statement:
SQL> UPDATE testtab SET numcol = numcol + 1;
The instance we’re using has a small buffer cache, so quite a bit of physical I/O is caused by the statement. After the UPDATE completes we look at v$sqlarea:
SQL> SELECT sql_id, application_wait_time appl, concurrency_wait_time concurr,
user_io_wait_time user_io
sql_text LIKE 'UPDATE testtab SET numcol%';
------------- --------- --------- -----------
038m56cp4am0c
fd5mxhdbf09ny
SQL> SELECT sql_id, sql_text
sql_id IN ('fd5mxhdbf09ny','038m56cp4am0c');
------------- -------------------------------------------------------------
038m56cp4am0c UPDATE testtab SET numcol = numcol + 1 WHERE ROWNUM & 1000
fd5mxhdbf09ny UPDATE testtab SET numcol = numcol + 1
So we see that the first statement (locking rows) spent 178.5 seconds (178,500,000 microseconds) waiting on events in the Application wait class and 0.02 seconds waiting on events in the User I/O wait class. If we recall from the discussion of wait classes, the TX enqueue for row contention is in the Application wait class, and data file reads are in the User I/O wait class. The second statement, which required more disk reads, shows 105 seconds of User I/O waits and a very small amount of concurrency waits.
While the currently available documentation from Oracle does not provide much information about these new columns in v$sql and v$sqlarea, they appear to hold much promise for diagnosing query performance problems.
v$session_wait_history
Up through Oracle 9i, the v$ views show us only the most recent wait event for each session. Even though wait times can accumulate to greatly slow down a process, many waits are very short (from a human perspective) individually. So, it’s often difficult to grab information on a wait event as it is happening. The v$session_wait_history view, new in Oracle 10g, helps by showing the last ten wait events each session has experienced
As an example, the following query shows the ten most recent wait events for session 154:
SQL> SELECT
sid, seq#, event, wait_time, p1, p2, p3
v$session_wait_history
ORDER BY seq#;
SID SEQ# EVENT
--- ---- ------------------------ ---------- ------ ------ ------
1 db file sequential read
2 log buffer space
3 log buffer space
4 db file sequential read
5 db file sequential read
6 db file sequential read
7 log buffer space
8 db file sequential read
9 db file sequential read
10 log buffer space
The seq# column is supposed to show the chronological sequence of the wait events, with 1 being the most recent wait event in the session. On our release 10.1.0.3 databases on Solaris, the seq# column behaves differently—making it difficult to tell which wait event is the most recent. In any case, note that this seq# value differs from the seq# column in v$session, which is incremented for each wait experienced by the session throughout the life of the session.
In the above query, we see that the session’s most recent waits alternated between single-block disk reads and log buffer space. This makes sense, since the SQL that the session was performing looked like:
INSERT INTO table1 (column1, column2)
SELECT column1, column2
From this list of recent waits, we can also drill down to get more detail.
The p1 and p2 values for db file sequential read indicate the file and block numbers being read, so we can quickly determine what segment was being read.
The columns in v$session_wait_history are:
SQL> DESCRIBE v$session_wait_history
----------------------------------------- -------- ----------------------------
VARCHAR2(64)
VARCHAR2(64)
VARCHAR2(64)
VARCHAR2(64)
WAIT_COUNT
The v$session view has been enhanced in Oracle 10g with several new columns which are quite useful. The wait event columns from v$session_wait have been added to v$session. In previous releases of Oracle, to get more detailed information about a session experiencing waits (such as what SQL the waiting session is executing), we had to join v$session_wait with v$session, as in:
SQL> SELECT s.sid, w.state, w.event, w.seconds_in_wait siw,
s.sql_address, s.sql_hash_value hash_value, w.p1, w.p2, w.p3
v$session s, v$session_wait w
s.sid = w.sid
s.sid = 154;
In Oracle 10g we can get all of this information from v$session:
SQL> SELECT sid, state, event, seconds_in_wait siw,
sql_address, sql_hash_value hash_value, p1, p2, p3
sid = 154;
SIW SQL_ADDRESS
HASH_VALUE
--- ------- ----------------------- --- ---------------- ---------- --- ---- ---
154 WAITING db file sequential read
Two additional columns have been added to v$session that are helpful for wait event analysis: blocking_session and blocking_session_status. The blocking_session column contains the session id (SID) of the holder of the resource that the waiting session is waiting for.
The blocking_session_status column indicates the validity of the contents of the blocking_session column.
If blocking_session_status is VALID, a valid SID is present in the blocking_session column. In the past, if we saw that a session was waiting for a resource, we would have to do additional queries to determine who was holding the resource. If the resource was an enqueue lock, we would have to query v$lock (sometimes a very expensive query) to determine who was holding the lock. Now we can find out who is holding the lock much more quickly:
SQL> SELECT sid, blocking_session, username,
blocking_session_status status
blocking_session_status = 'VALID';
SID BLOCKING_SESSION USERNAME STATUS
--- ---------------- -------- -----------
157 TSUTTON
If we combine this with the wait event information now available in v$session, we see:
SQL> SELECT sid, blocking_session, username,
event, seconds_in_wait siw
blocking_session_status = 'VALID';
SID BLOCKING_SESSION USERNAME EVENT
--- ---------------- -------- ------------------------------ ---
157 TSUTTON
enq: TX - row lock contention
v$event_histogram
The v$system_event view shows the number of waits, total time waited, and average wait time for a given wait event name (system-wide since instance startup). However, this aggregation can cloud the picture, because a small number of long waits can skew the data. For example, consider the following query from v$system_event:
SQL> SELECT event, total_waits, time_waited, average_wait
v$system_event
event = 'enq: TX - row lock contention';
TOTAL_WAITS TIME_WAITED AVERAGE_WAIT
----------------------------- ----------- ----------- ------------
enq: TX - row lock contention
We see that there have been 17,218 waits and that the average wait time was 1.22 seconds, but we have no idea how the wait times are distributed. Were all of these waits roughly the same length? Were most of them under one second long and a few really long waits threw off the average? We can’t tell from v$system_event. However, in Oracle 10g we can look at v$event_histogram for a more complete picture:
SQL> SELECT event, wait_time_milli, wait_count
v$event_histogram
event = 'enq: TX - row lock contention';
WAIT_TIME_MILLI WAIT_COUNT
----------------------------- --------------- ----------
enq: TX - row lock contention
enq: TX - row lock contention
enq: TX - row lock contention
enq: TX - row lock contention
enq: TX - row lock contention
enq: TX - row lock contention
enq: TX - row lock contention
enq: TX - row lock contention
enq: TX - row lock contention
enq: TX - row lock contention
enq: TX - row lock contention
enq: TX - row lock contention
enq: TX - row lock contention
We see that very few of the waits were anywhere near 1.22 seconds. Nearly 60% of the waits were less than 0.128 seconds (with most of those between 16 milliseconds and 64 milliseconds), and most of the remaining waits were between 2.048 seconds and 4.096 seconds (at which point some timed out and started new waits). In this way, the v$event_histogram view gives us a more accurate picture of wait times summarized by event name.
The columns of v$event_histogram are:
SQL> DESCRIBE v$event_histogram
----------------------------------------- -------- ----------------------------
VARCHAR2(64)
WAIT_TIME_MILLI
WAIT_COUNT
v$system_wait_class and v$session_wait_class
The two new views v$system_wait_class and v$session_wait_class enable us to get system and session wait information summarized by wait classes. This gives us a higher level view of what is happening in the system or session, rather than focusing on individual events. The views are roughly equivalent to the views v$system_event and v$session_event, except that they roll up the events by wait class. The wait times are expressed in centiseconds since instance startup for v$system_wait_class and centiseconds since session connection for v$session_wait_class.
The following queries show how much time (in centiseconds) has been spent on waits in each class across the system since instance start and for one specific session since that session began:
SQL> SELECT
wait_class, time_waited
v$system_wait_class
ORDER BY time_waited DESC;
WAIT_CLASS
TIME_WAITED
------------- -----------
System I/O
Configuration
Application
Concurrency
SQL> SELECT
wait_class, time_waited
v$session_wait_class
ORDER BY time_waited DESC;
WAIT_CLASS
TIME_WAITED
------------- -----------
Configuration
Application
Since the wait times shown in these views are aggregations since system or session startup, these views are best used by taking samples and comparing the results to determine waits over a period of time. For instance, you could get data for the entire instance at time T1:
DROP TABLE swc_
CREATE TABLE swc_snap
SELECT wait_class, total_waits, time_waited
v$system_wait_
And then, at time T2 a while later, get a summary of waits between T1 and T2:
a.wait_class, (a.time_waited - b.time_waited) tm_waited
v$system_wait_class a, swc_snap b
a.wait_class = b.wait_class
a.total_waits > NVL (b.total_waits, 0)
ORDER BY tm_waited DESC;
WAIT_CLASS
--------------- ----------
Application
System I/O
Active Session History
In previous releases of Oracle, the detailed information displayed in v$session_wait could prove extremely helpful in diagnosing performance problems—if you queried the view at the right time. The v$session_wait_history view in Oracle 10g makes it a little easier to catch detailed information by preserving the last ten waits for each session. But what if you want detailed information about a session’s waits for a period further back in time? This is where the Active Session History feature of Oracle 10g—ASH for short—comes in handy. ASH makes detailed information about a sampling of waits encountered by all sessions available to us for a very long time.
In Oracle 10g, a new background daemon process called MMNL queries v$session once each second and stores information about all active sessions in a circular buffer in memory accessible by a new view called v$active_session_history. How far back you can look at sessions in this view depends on session activity and how much memory Oracle allocated for ASH. Oracle’s goal is to keep at least a few hours of session data available in this view. The v$active_session_history view includes much of the detailed wait event information shown in v$session:
SQL> DESCRIBE v$active_session_history
----------------------------------------- -------- ----------------------------
SAMPLE_TIME
TIMESTAMP(3)
SESSION_ID
SESSION_SERIAL#
VARCHAR2(13)
SQL_CHILD_NUMBER
SQL_PLAN_HASH_VALUE
SQL_OPCODE
SERVICE_HASH
SESSION_TYPE
VARCHAR2(10)
SESSION_STATE
VARCHAR2(7)
QC_SESSION_ID
QC_INSTANCE_ID
VARCHAR2(64)
TIME_WAITED
CURRENT_OBJ#
CURRENT_FILE#
CURRENT_BLOCK#
VARCHAR2(48)
VARCHAR2(48)
VARCHAR2(32)
VARCHAR2(64)
As you can see, v$active_session_history captures the essential wait-related data from v$session. It also captures useful information about the SQL statement currently being executed, as well as current object number, file, and block being accessed. When a wait that was sampled by ASH completes, Oracle fills in the time_waited column for the row in v$active_session_history with the actual duration of the wait.
The Automatic Workload Repository, which we will discuss in the next section, writes data from v$active_session_history to disk at regular intervals, preserving one sample every ten seconds from each active session. So, active session information remains accessible—although with less detail—even after the data has aged out of v$active_session_history.
Because ASH is always “on,” you always have access to detailed information about waits encountered in sessions within the last few hours. This means that if a user complains about a performance problem, you may be able to query v$active_session_history and gain insight into the problem without having to initiate an extended SQL trace or start a close watch of v$session while they reproduce the problem.
An important thing to keep in mind about v$active_session_history, however, is that it is populated by sampling v$session once each second. A session may encounter many different waits during a one second period, but only the one wait that was in progress when ASH collected its sample will be recorded in v$active_session_history. For this reason, ASH is valuable for general aggregate queries but not for precise counting of individual events or determining minimum or maximum wait times. Statistically speaking, the data collected by ASH is probably more accurate over a larger time interval and/or number of sessions.
For example, you might query v$active_session_history to see what percentage of time over the last two hours a particular group of sessions spent waiting on disk reads. However, using this view to determine how many disk read waits a session encountered in the last minute probably will not yield very accurate results.
Even though ASH data is only a sampling of active sessions, the information can prove to be quite useful. For example, the following query shows that sessions running the ARXENV application over the last two hours encountered a great deal of row-level lock contention:
SQL> SELECT
DECODE (session_state, 'WAITING', event, NULL) event,
session_state, COUNT(*), SUM (time_waited) time_waited
v$active_session_history
module = 'ARXENV'
sample_time > SYSDATE - (2/24)
GROUP BY DECODE (session_state, 'WAITING', event, NULL),
SESSION_STATE COUNT(*) TIME_WAITED
------------------------------ ------------- -------- -----------
log file sync
db file scattered read
db file sequential read
control file sequential read
SQL*Net break/reset to client
enq: TX - row lock contention
In addition to running queries against the v$active_session_history view, you can use Enterprise Manager to run reports that will display ASH data.
Although ASH runs on all Oracle 10g databases by default, you are not allowed to query the v$active_session_history view (or run the corresponding reports in Enterprise Manager) unless you have purchased the Diagnostic Pack.
Automatic Workload Repository
Oracle 10g includes another significant facility relevant to the wait event interface. It’s known as the Automatic Workload Repository—or AWR for short. AWR is basically a next-generation Statspack. By default, AWR collects an hourly snapshot of database performance information, storing the data in tables in the SYS schema. AWR is configured automatically when you create an Oracle 10g database. You can call the dbms_workload_repository package to collect a snapshot on demand, purge a snapshot or range of snapshots, or change the snapshot interval or retention period. (By default snapshots are collected at the top of each hour and are purged after seven days.)
AWR collects the same type of data that Statspack does—including system-level statistics, resource-intensive SQL, and of course instance-wide wait event information. AWR also collects data that is new for Oracle 10g, such as time model statistics (which we will discuss in the next section). As an aside, the Oracle 10g version of Statspack also collects a lot of this new information, including time model statistics.
You can generate an AWR report of database activity between two snapshots by running the awrrpt.sql script in the rdbms/admin directory under $ORACLE_HOME. This script offers reports formatted as plain text or HTML. The reports will look familiar if you have used Statspack before. You can use Enterprise Manager to generate AWR reports as well.
AWR offers many benefits over Statspack. For one, it is more tightly integrated into the Oracle kernel, reducing resource requirements and overhead when collecting snapshots. AWR snapshots also include ASH data from v$active_session_history, providing session-level information to complement the system-level data collection familiar to Statspack users.
Data collected by AWR is made easily accessible via views with names that start DBA_HIST. This enables you to write your own reports that extract just the data you need to address a specific situation, if for some reason you don’t find what you need in the standard AWR report. For example, the following query displays the two most recent snapshot IDs:
SQL> SELECT snap_id, begin_interval_time, end_interval_time
snap_id, begin_interval_time, end_interval_time
dba_hist_snapshot
ORDER BY end_interval_time DESC
ROWNUM &= 2;
SNAP_ID BEGIN_INTERVAL_TIME
END_INTERVAL_TIME
---------- ------------------------- -------------------------
362 10-MAR-05 04.00.02.018 PM 10-MAR-05 05.00.36.581 PM
361 10-MAR-05 03.00.25.885 PM 10-MAR-05 04.00.02.018 PM
Just like ASH, AWR runs on all Oracle 10g databases by default. Also like ASH, you are not allowed to query the AWR views (or run AWR reports) unless you have licensed the Diagnostic Pack. Because AWR consumes system resources when collecting snapshots and uses up storage in the SYSAUX tablespace, you may want to disable the collection of AWR snapshots if you are not licensed to use AWR. This may be done by using the dbms_workload_repository package. If AWR is not available to you, Statspack is still a good way to go in Oracle 10g.
Time Model Statistics
Oracle 10g introduces a new concept called Time Model Statistics. This information provides yet another way to see how time is spent, and with greater detail than was available previously. The v$sys_time_model view shows time model statistics for the entire system since instance startup, while the v$sess_time_model view shows time model statistics for each session since session start. The columns in these two views are as follows:
SQL> DESCRIBE v$sys_time_model
---------------------------------------- -------- ---------------------------
VARCHAR2(64)
SQL> DESCRIBE v$sess_time_model
---------------------------------------- -------- ---------------------------
VARCHAR2(64)
A sample query from v$sys_time_model shows the following:
SQL> SELECT
stat_name, value / 1000000 seconds
v$sys_time_model
ORDER BY seconds DESC;
------------------------------------------------ ----------
sql execute elapsed time
background elapsed time
PL/SQL execution elapsed time
background cpu time
parse time elapsed
hard parse elapsed time
PL/SQL compilation elapsed time
sequence load elapsed time
connection management call elapsed time
failed parse elapsed time
hard parse (sharing criteria) elapsed time
hard parse (bind mismatch) elapsed time
failed parse (out of shared memory) elapsed time
Java execution elapsed time
inbound PL/SQL rpc elapsed time
This query shows us a lot more information about how Oracle sessions have spent their time (categorically) than v$sysstat and v$sesstat do. Of course, we have to know how to interpret this information before we can put it to work for us. Values in these views are shown in microseconds, and they do not include background processes unless “background” appears in the statistic name. The “DB time” statistic shows elapsed time spent on database calls (user processes only). This amounts to time spent on the CPU or waiting on non-idle wait events. For a description of the other time model statistics, see the v$sess_time_model view listing in the Oracle 10g Database Reference manual.
From this query, among many other useful facts, we can see that no time has been spent executing Java, very little time has been spent hard parsing or compiling PL/SQL, background processes have used about 10% of the CPU time, and about 11% of the elapsed time for user sessions was spent on PL/SQL execution.
Tracing Facility Improvements
The extended SQL trace facility, also known as event 10046, allows us to capture in a trace file detailed information about every wait event encountered by a database session. This feature has been available in Oracle for a long time. However, Oracle 10g offers some helpful improvements in this area.
Enabling extended SQL trace has always been a bit of a nuisance. In earlier releases of Oracle, you had to use a clumsy ALTER SESSION SET EVENTS statement or—worse yet—call the undocumented dbms_system.set_ev procedure to set the 10046 event in another user’s session. In Oracle 8i the dbms_support package was introduced to make this step easier, but the package was missing from many releases of Oracle and usually was not installed by default.
Oracle 10g introduces the new dbms_monitor package. This package, among many other things, makes it very easy to turn extended SQL trace on and off in any Oracle session. With one easy to remember call, you can turn extended SQL trace on or off, with wait events and/or bind variables captured in the trace file:
SQL> DESCRIBE dbms_monitor
PROCEDURE SESSION_TRACE_DISABLE
Argument Name
In/Out Default?
------------------------------ ----------------------- ------ --------
SESSION_ID
BINARY_INTEGER
SERIAL_NUM
BINARY_INTEGER
PROCEDURE SESSION_TRACE_ENABLE
Argument Name
In/Out Default?
------------------------------ ----------------------- ------ --------
SESSION_ID
BINARY_INTEGER
SERIAL_NUM
BINARY_INTEGER
If the session_id parameter is not specified or set to NULL, your own session will be traced. Thus, the following two statements should be equivalent:
ALTER SESSION SET events '10046 trace name context forever, level 12';
EXECUTE dbms_monitor.session_trace_enable (waits=>TRUE, binds=>TRUE);
In Oracle 9i and earlier, extended SQL trace was easy to use if your application connected to the Oracle database via a dedicated server connection. If the shared server architecture was used, each shared server process that serviced a request from the session being traced would write its data to a separate trace file. Furthermore, tracing sessions in a connection pool environment became difficult because one Oracle session could actually process requests for many different end-user sessions.
The dbms_monitor package in Oracle 10g addresses this problem. Instead of enabling extended SQL trace for a specific Oracle session, you can enable it for a specific client identifier or combination of service, module, and action. Any time any Oracle session has the specified client identifier or combination of service, module, and action, the session will be traced. Sessions can set or clear their client identifier at will by calling the dbms_session package, and they can set their module and action by calling the dbms_application_info package.
Suppose a web-based application uses a pool of 30 database connections to serve user requests and maintains a current_sessions table to keep track of the state of each end-user session. When a user clicks a button in their browser window, the application server receives the HTTP request and hands it off to an application server process. The application server process grabs a free database connection from the pool and accesses the database as necessary to service the request. It is likely that subsequent requests from the same user will be processed using different database connections.
In Oracle 9i and earlier it would have been very difficult to trace the one user’s database activity in this environment. The user’s database accesses are spread among multiple Oracle server processes in the connection pool. Moreover, each of those Oracle processes is handling requests from many different end users.
With dbms_monitor in Oracle 10g, the application could be modified in a way to make extended SQL trace a whole lot easier. We mentioned that the application uses the current_sessions table to maintain state for each end user session. Each time the application server grabs a database connection from the pool, it could set the client identifier for the Oracle session to the session_id from the current_sessions table before doing any database access for that end user session. Then the application could clear the client identifier before returning the database connection to the pool. The Oracle calls could look like this:
EXECUTE dbms_session.set_identifier ('session_id');
...do the work for this end user session...
EXECUTE dbms_session.clear_identifier
To trace this end user session, we could now call the dbms_monitor package like this:
SQL> EXECUTE dbms_monitor.client_id_trace_enable -
('session_id', waits=>TRUE, binds=>TRUE);
This call to dbms_monitor will cause each Oracle process to write extended SQL trace data to a trace file for all calls that occur while the client identifier for the session is set to the specified value. However, each Oracle process will write to its own trace file. This will cause the trace data to be split over multiple files. To address this problem, Oracle 10g provides a new command-line utility called trcsess. The trcsess utility reads multiple trace files and consolidates entries from the various files that meet the specified criteria into one trace file that can be processed by TKPROF. To consolidate the trace data for our current example, we could use the following commands:
$ cd $ORACLE_BASE/admin/$ORACLE_SID/udump
$ trcsess output=/home/rschrag/case1403/case1403-trial1.trc \
clientid=session_id
In this way the dbms_monitor package and trcsess utility in Oracle 10g make it a lot easier to collect extended SQL trace data from an end user’s session when connection pooling or other session aggregation techniques are used by the application server tier.
Conclusion
Oracle 10g includes many enhancements to the wait event interface that should make performance management using wait event methodologies easier than ever. Some enhancements, such as descriptive wait event names, wait classes, and the session_trace_enable procedure in the dbms_monitor package, are simple conveniences that make our jobs easier. These enhancements don’t give us any information or power that we didn’t have before. Other enhancements, however, such as time model statistics, v$event_histogram, and new columns in v$sql and v$sqlarea, provide us with helpful timing and wait information that was previously unavailable.
Although as of this writing documentation on these new features is incomplete and discussion on Metalink is surprisingly sparse, many of these enhancements will likely prove quite valuable to the Oracle DBA responsible for performance management of a complex Oracle system.
About the Authors
Terry Sutton, OCP, has been an Oracle DBA for eleven years, and has worked in the information technology area for 18 years. Since 2000, Terry has been a Senior Staff Consultant at Database Specialists, performing assignments ranging from production database administration to emergency troubleshooting with a particular focus on Oracle database performance tuning. You may contact Terry by email at .
Roger Schrag, OCP, has been an Oracle DBA and application architect for over 15 years. He began his career at Oracle Corporation on the Oracle Financials development team. In 1995, he founded Database Specialists, Inc., a boutique consulting firm specializing in Oracle database technology, remote administration, and performance tuning. Since that time, Roger has focused his expertise in the area of performance optimization. Roger is a frequent speaker at Oracle OpenWorld and the International Oracle Users Group (IOUG) Live conferences, where he has frequently been voted in the Top 10% of speakers. Roger has been an Oracle Masters Class instructor for the IOUG and is Director of Conference Programming for the Northern California Oracle Users Group (NoCOUG). He can be reached at .
Still Looking for Help on this Subject?
Get a ConsultationWe would be happy to talk with you about our services and how our senior-level database team might help you. Call Database Specialists at 415-344-0500 or 888-648-0500 or fill out a
request form. Complimentary NewsletterIf you'd like to receive our complimentary monthly newsletter with database tips and new white paper announcements, sign up for .