"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.
By querying v$ views, we can see what events processes are waiting
on to an amazing level of detail.
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.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.
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. 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.
If you want a quick instance wide wait event status, showing which events are the biggest contributors to total wait time, you can use the following query :
select event, total_waits,time_waited from
V$system_event
where event NOT IN
('pmon timer',
'smon timer', 'rdbms ipc reply', 'parallel deque wait',
'virtual circuit',
'%SQL*Net%', 'client message', 'NULL event')
order by time_waited desc;
EVENT
TOTAL_WAITS
TIME_WAITED
------------------------
-------------
-------------
db file sequential
read
35051309
15965640
latch
free
1373973
1913357
db file scattered
read
2958367
1840810
enqueue
2837
370871
buffer busy
waits
444743
252664
log file parallel
write
146221
123435
Here are some of the most common wait events and what
they mean:
1. DB File Scattered Read.
That generally happens during a full scan of a table or Fast
Full Index Scans. As
full table scans are pulled into memory, they rarely fall
into contiguous buffers but instead are scattered throughout
the buffer cache. A large number here indicates that your
table may have missing indexes, statistics are not updated
or your indexes are not used. Although it may be more
efficient in your situation to perform a full table scan
than an index scan, check to ensure that full table scans
are necessary when you see these waits. Try to cache small
tables to avoid reading them in over and over again, since a
full table scan is put at the cold end of the LRU (Least
Recently Used) list. You
can use the report to help identify the query in question
and fix it.
The init.ora
parameter db_file_multiblock_read_count
specifies the maximum numbers of blocks read in that way.
Typically, this parameter should have values of 4-16 independent
of the size of the database but with higher values needed with
smaller Oracle block sizes. If you have a high wait time for
this event, you either need to reduce the cost of I/O, e.g. by
getting faster disks or by distributing your I/O load better, or
you need to reduce the amount of full table scans by tuning SQL
statements. The appearance of the‘db file scattered read’ and ‘db file sequential read’events
may not necessarily indicate a problem, as IO is a normal
activity on a healthy instance. However, they can indicate
problems if any of the following circumstances are true:
• The data-access method is bad (that is, the SQL statements are
poorly tuned), resulting in unnecessary or inefficient IO
operations
• The IO system is overloaded and performing poorly
• The IO system is under-configured for the load
• IO operations are taking too long
If this Wait Event is a significant
portion of Wait Time then a number of approaches are possible:
o Find which SQL statements perform Full Table or Fast Full
Index scans and tune them to make sure these scans are necessary
and not the result of a suboptimal plan.
- The view V$SQL_PLAN view can help:
For Full Table scans:
select sql_text from
v$sqltext t, v$sql_plan p
where
t.hash_value=p.hash_value
and p.operation='TABLE ACCESS'
and
p.options='FULL'
order by
p.hash_value, t.piece;
For Fast Full Index scans:
select sql_text from
v$sqltext t, v$sql_plan p
where
t.hash_value=p.hash_value
and p.operation='INDEX'
and
p.options='FULL SCAN'
order by
p.hash_value, t.piece;
o In cases where such multiblock scans
occur from optimal execution plans it is possible to tune the
size of multiblock I/Os issued by Oracle by setting the instance
parameter DB_FILE_MULTIBLOCK_READ_COUNT so that:
DB_BLOCK_SIZE x DB_FILE_MULTIBLOCK_READ_COUNT = max_io_size of
system
Query tuning should be used to optimize online SQL to use
indexes.
2. DB File Sequential Read.
Is the wait
that comes from the physical side of the database. It related
to memory starvation and non selective index use. Sequential
read is an index read followed by table read because it is
doing index lookups which tells exactly which block to go to.
This could indicate poor
joining order of tables or un-selective indexes in your
SQL or waiting for writes to TEMP space (direct loads,
Parallel DML (PDML) such as parallel updates. It could mean that a lot of index reads/scans
are going on. Depending on the problem it may help to tune
PGA_AGGREGATE_TARGET and/or DB_CACHE_SIZE.
The
sequential read event identifies Oracle reading blocks
sequentially, i.e. one after each other. It is normal for this
number to be large for a high-transaction, well-tuned system,
but it can indicate problems in some circumstances. You should
correlate this wait statistic with other known issues within the
report, such as inefficient SQL. Check to ensure that index
scans are necessary, and check join orders for multiple table
joins. The DB_CACHE_SIZE will also be a determining factor in
how often these waits show up. Problematic hash-area joins
should show up in the PGA memory, but they're also memory hogs
that could cause high wait numbers for sequential reads. They
can also show up as direct path read/write waits. These
circumstances are usually interrelated. When they occur in
conjunction with the appearance of the 'db file scattered read' and 'db file sequential read' in
the Top 5 Wait Events section, first you should examine the SQL
Ordered by Physical Reads section of the report, to see if it
might be helpful to tune the statements with the highest resource
usage.
It could be because the indexes are fragmented. If that is the
case, rebuilding the index will compact it and will produce to
visit less blocks.
Then, to determine whether there is a potential I/O bottleneck,
examine the OS I/O statistics for corresponding symptoms. Also
look at the average time per read in the Tablespace and File I/O
sections of the report. If many I/O-related events appear high in
the Wait Events list, re-examine the host hardware for disk
bottlenecks and check the host-hardware statistics for indications
that a disk reconfiguration may be of benefit.
Block reads are fairly inevitable so the aim should be to minimize
unnecessary I/O. I/O for sequential reads can be reduced by tuning
SQL calls that result in full table scans and using the
partitioning option for large tables.
3. Free Buffer Waits.
When a session needs a free buffer and cannot find one, it will
post the database writer process asking it to flush dirty blocks
(No place to put a new block). Waits in this category may
indicate that you need to increase
the DB_BUFFER_CACHE, if all your SQL is tuned. Free
buffer waits could also indicate that unselective SQL is causing
data to flood the buffer cache with index blocks, leaving none
for this particular statement that is waiting for the system to
process. This normally indicates that there is a substantial
amount of DML (insert/update/delete) being done and that the
Database Writer (DBWR) is not writing quickly enough; the buffer
cache could be full of multiple versions of the same buffer,
causing great inefficiency. To address this, you may want to
consider accelerating
incremental checkpointing, using more DBWR processes,
or increasing the number of physical disks. To investigate if
this is an I/O problem, look at the report I/O Statistics.
Increase the DB_CACHE_SIZE; shorten the checkpoint; tune the
code to get less dirty blocks, faster I/O, use multiple DBWR’s.
4. Buffer Busy Waits. A buffer busy wait happens when multiple
processes concurrently want to modify the same block in the
buffer cache. This typically happens during massive parallel
inserts if your tables do not have free lists and it can happen
if you have too few rollback segments. Buffer busy waits should not be greater than 1 percent.
Check the Buffer Wait Statistics section (or V$WAITSTAT) to find
out if the wait is on a segment header. If this is the case,
increase the freelist groups or increase the pctused to pctfree
gap. If the wait is on an undo header, you can address this by
adding rollback segments; if it's on an undo block, you need to
reduce the data density on the table driving this consistent
read or increase the DB_CACHE_SIZE. If the wait is on a data
block, you can move data to another block to avoid this hot
block, increase the freelists on the table, or use Locally
Managed Tablespaces (LMTs). If it's on an index block, you
should rebuild the index, partition the index, or use a reverse
key index. To prevent buffer busy waits related to data blocks,
you can also use a smaller block size: fewer records fall within
a single block in this case, so it's not as "hot." When a DML
(insert/update/ delete) occurs, Oracle writes information into
the block, including all users who are "interested" in the state
of the block (Interested Transaction List, ITL). To decrease
waits in this area, you can increase the initrans, which will
create the space in the block to allow multiple ITL slots. You
can also increase the pctfree on the table where this block
exists (this writes the ITL information up to the number
specified by maxtrans, when there are not enough slots built
with the initrans that is specified). Buffer busy waits can be
reduced by using reverse-key indexes for busy indexes and by
partitioning busy tables.
Buffer Busy Wait on Segment
Header – Add freelists (if inserts) or freelist groups
(esp. RAC). Use ASSM.
Buffer Busy Wait on Data
Block – Separate ‘hot’ data; potentially use reverse key
indexes; fix queries to reduce the blocks popularity, use
smaller blocks, I/O, Increase initrans and/or maxtrans (this
one’s debatable). Reduce records per block
Buffer Busy Wait on
Undo Header – Add rollback segments or increase size of
segment area (auto undo)
Buffer Busy Wait on
Undo block – Commit more (not too much) Larger rollback
segments/area. Try to fix the SQL.
5. Latch Free. Latches are
low-level queuing mechanisms (they're accurately referred to as
mutual exclusion mechanisms) used to protect shared memory
structures in the system global area (SGA). Latches are like
locks on memory that are very quickly obtained and released.
Latches are used to prevent concurrent access to a shared memory
structure. If the latch is not available, a latch free miss is
recorded. Most latch problems are related to the failure to use
bind variables (library cache latch), redo generation issues
(redo allocation latch), buffer cache contention issues (cache
buffers LRU chain), and hot blocks in the buffer cache (cache
buffers chain). There are also latch waits related to bugs;
check MetaLink for bug reports if you suspect this is the case.
When latch miss ratios are greater than 0.5 percent, you should
investigate the issue. If
latch free waits are in the Top 5 Wait Events or high in the
complete Wait Events list, look at the latch-specific sections of
the report to see which latches are contended for.
6. Enqueue. An enqueue is a lock that protects a shared
resource. Locks protect shared resources, such as data in a
record, to prevent two people from updating the same data at the
same time application, e.g. when a select for update is
executed.. An enqueue includes a queuing mechanism, which is
FIFO (first in, first out). Note that Oracle's latching
mechanism is not FIFO. Enqueue waits usually point to the ST
enqueue, the HW enqueue, the TX4 enqueue, and the TM enqueue.
The ST enqueue is used for space management and allocation for
dictionary-managed tablespaces. Use LMTs, or try to preallocate
extents or at least make the next extent larger for problematic
dictionary-managed tablespaces. HW enqueues are used with the
high-water mark of a segment; manually allocating the extents
can circumvent this wait. TX4s are the most common enqueue
waits. TX4 enqueue waits are usually the result of one of three
issues. The first issue is duplicates in a unique index; you
need to commit/rollback to free the enqueue. The second is
multiple updates to the same bitmap index fragment. Since a
single bitmap fragment may contain multiple rowids, you need to
issue a commit or rollback to free the enqueue when multiple
users are trying to update the same fragment. The third and most
likely issue is when multiple
users are updating the same block. If there are no free
ITL slots, a block-level lock could occur. You can easily avoid
this scenario by increasing the initrans and/or maxtrans to
allow multiple ITL slots and/or by increasing the pctfree on the
table. Finally, TM enqueues occur during DML to prevent DDL to
the affected object. If you have foreign keys, be sure to index them to avoid
this general locking issue.
Enqueue - ST
Use LMT’s or pre-allocate large extents
Enqueue - HW
Pre-allocate extents above HW (high water mark.)
Enqueue – TX
Increase initrans and/or maxtrans (TX4) on (transaction) the
table or index. Fix locking issues if TX6. Bitmap
(TX4) & Duplicates in Index (TX4).
Enqueue - TM
Index foreign keys; Check application (trans. mgmt.) locking of
tables. DML Locks.
7. Log Buffer Space
Look at increasing log buffer size. This wait occurs because you
are writing the log buffer faster than LGWR can write it to the
redo logs, or because log
switches are too slow. To address this problem,
increase the size of the redo log files, or increase the size of
the log buffer, or get faster disks to write to. You might even
consider using solid-state disks, for their high speed.
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.
8. Log File Switch
log file switch (checkpoint incomplete): May indicate excessive
db files or slow IO subsystem
log file switch (archiving needed): Indicates archive
files are written too slowly
log file switch completion: May need more log files per
May indicate excessive db files or slow IO subsystem. All commit
requests are waiting for "logfile switch (archiving needed)" or
"logfile switch (chkpt. Incomplete)." Ensure that the archive
disk is not full or slow. DBWR may be too slow because of I/O.
You may need to add more or larger redo logs, and you may
potentially need to add database writers if the DBWR is the
problem.
9. Log File Sync
Could indicate excessive commits. A Log File Sync happens each
time a commit (or rollback) takes place. If there are a lot of
waits in this area then you may want to examine your application
to see if you are committing too frequently (or at least more
than you need to). When a user commits or rolls back data, the
LGWR flushes the session's redo from the log buffer to the redo
logs. The log file sync process must wait for this to
successfully complete. To reduce wait events here, try to commit
more records (try to commit a
batch of 50 instead of one at a time, use BULKS, , for example).
Put redo logs on a faster disk, or alternate redo logs on
different physical disks (with no other DB Files, ASM, etc) to
reduce the archiving effect on LGWR. Don't use RAID 5, since it
is very slow for applications that write a lot; potentially
consider using file system direct I/O or raw devices, which are
very fast at writing information. The associated event, ‘log
buffer parallel write’ is used by the redo log writer process,
and it will indicate if your actual problem is with the log file
I/O. Large wait times for this event can also be caused by
having too few CPU resources available for the redolog writer
process.
10. Idle Event. There are several idle wait events listed
after the output; you can ignore them. Idle events are generally
listed at the bottom of each section and include such things as
SQL*Net message to/from client and other background-related
timings. Idle events are listed in the stats$idle_event table.
11. global
cache
cr request: (OPS) This wait event shows the amount of
time that an instance has waited for a requested data block for
a consistent read and the transferred block has not yet arrived
at the requesting instance. See Note 157766.1 'Sessions Wait
Forever for 'global cache cr request' Wait Event in OPS or RAC'.
In some cases the 'global cache cr request' wait event may be
perfectly normal if large buffer caches are used and the same
data is being accessed concurrently on multiple instances.
In a perfectly tuned, non-OPS/RAC database, I/O wait events
would be the top wait events but since we are avoiding I/O's
with RAC and OPS the 'global cache cr request' wait event often
takes the place of I/O wait events.
12.
library cache pin: Library cache
latch contention may be caused by not using bind variables. It
is due to excessive parsing of SQL statement.
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.
13. CPU
time
This is not really a wait event (hence, the new name), but
rather the sum of the CPU used by this session, or the amount
of CPU time used during the snapshot window. In a heavily
loaded system, if the CPU time event is the biggest event,
that could point to some CPU-intensive processing (for
example, forcing the use of an index when a full scan should
have been used), which could be the cause of the bottleneck.
When CPU Other is a significant component of total Response
Time the next step is to find the SQL statements that access
the most blocks. Block accesses are also known as Buffer Gets
and Logical I/Os. The report lists such SQL statements in
section SQL ordered by Gets.
14. DB File Parallel
Read If you are doing a lot of partition
activity then expect to see that wait even. it could be a
table or index partition. This Wait Event is used when Oracle
performs in parallel reads from multiple datafiles to
non-contiguous buffers in memory (PGA or Buffer Cache). This
is done during recovery operations or when buffer prefetching
is being used as an optimization i.e. instead of performing
multiple single-block reads. If this wait is an important
component of Wait Time, follow the same guidelines as 'db file
sequential read'.
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.
15. PX qref latch
Can often mean that the Producers are producing data quicker
than the Consumers can consume it. Maybe we could increase
parallel_execution_message_size to try to eliminate some of
these waits or we might decrease the degree of parallelism. If
the system workload is high consider to decrease the degree of
parallelism. If you have DEFAULT parallelism on your
object you can decrease the value of
PARALLEL_THREADS_PER_CPU. Have in mind DEFAULT
degree = PARALLEL_THREADS_PER_CPU * #CPU's
16. Log File Parallel
Write. It occurs when waiting for writes of REDO
records to the REDO log files to complete. The wait occurs in
log writer (LGWR) as part of normal activity of copying
records from the REDO log buffer to the current online log.
The actual wait time is the time taken for all the outstanding
I/O requests to complete. Even though the writes may be issued
in parallel, LGWR needs to wait for the last I/O to be on disk
before the parallel write is considered complete. Hence the
wait time depends on the time it takes the OS to complete all
requests.
Log file parallel write waits can be reduced by moving log
files to the faster disks and/or separate disks where there
will be less contention.
17. SQL*Net more data to
client
This means the instance is sending a lot of data to the
client. You can decrease this time by having the client bring
back less data. Maybe the application doesn't need to bring
back as much data as it is.
18. SQL*Net message to
client
The “SQL*Net message to client” Oracle metric indicates the
server (foreground process) is sending a message to the
client, and it can be used to identify throughput issues over
a network, especially distributed databases with slow database
links. The SQL*Net more data to client event happens when
Oracle writes multiple data buffers (sized per SDU) in a
single logical network call.
19. enq: TX - row lock
contention:
Oracle keeps data consistency with the help of locking
mechanism. When a particular row is being modified by the
process, either through Update/ Delete or Insert operation,
oracle tries to acquire lock on that row. Only when the
process has acquired lock the process can modify the row
otherwise the process waits for the lock. This wait situation
triggers this event. The lock is released whenever a COMMIT is
issued by the process which has acquired lock for the row.
Once the lock is released, processes waiting on this event can
acquire lock on the row and perform DML operation
|
|
|
| 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.
In Statspack, the 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. 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:
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, so by default this parameter is set to TRUE.
There are two common ways of collecting wait event information:
the Oracle extended trace (10046 event) and using V$ views; we
will focus on this one
Any user with the SELECT ANY TABLE system privilege or the
SELECT_CATALOG_ROLE role can query the v$ views. Only users who
can connect to the database as SYSDBA or execute the DBMS_SUPPORT
or DBMS_SYSTEM packages can activate wait event tracing in other
database sessions.
Oracle provides a number of views to aid in tuning; a few are:
* V$SYSTEM_EVENT, which gives you total system
waits for an event since database startup.
* V$SESSION_EVENT, All waits the session
encountered so far at the session level.
* V$SESSION_WAIT gives you what an active
session is waiting on at that point in time.
* V$SESSION, which gives you session
information and has a column ROW_WAIT_OBJ# that tells you the
object involved when joined with OBJECT_ID or DATA_OBJECT_ID in
DBA_OBJECTS.
There are several V$ views for tracking history called
V$%_HISTORY, including V$ACTIVE_SESSION_HISTORY (ASH), which
samples non-idle wait events every second and new columns in
V$SESSION to combine information in V$SESSION_WAIT. The
information is held for 30 minutes, then is stored in AWR:
DBA_HIST_ACTIVE_SESS_HIST
The V$SYSTEM_EVENT View
The v$system_event view shows one row for each wait event name,
along with the total number of times a process has waited for this
event, the number of timeouts, the total amount of time waited,
and the average wait time. All of these figures are cumulative for
all Oracle processes since the instance started. Wait events that
have not occurred at least once since instance startup do not
appear in this view. The v$system_event view has the following
columns:
Name Null? Type
----------------------------------------- -------- ------------------
EVENT VARCHAR2(64)
TOTAL_WAITS NUMBER
TOTAL_TIMEOUTS NUMBER
TIME_WAITED NUMBER
AVERAGE_WAIT NUMBER
TIME_WAITED_MICRO NUMBER
TOTAL_WAITS_FG NUMBER
TOTAL_TIMEOUTS_FG NUMBER
TIME_WAITED_FG NUMBER
AVERAGE_WAIT_FG NUMBER
TIME_WAITED_MICRO_FG NUMBER
EVENT_ID NUMBER
WAIT_CLASS_ID NUMBER
WAIT_CLASS# NUMBER
WAIT_CLASS VARCHAR2(64)
EVENT = The name of the wait event. You can see a list of all
wait event names known to your Oracle kernel with the following
query:
SELECT name FROM v$event_name order by 1;
TOTAL_WAITS = The total number of times a process has waited for
this event since instance startup.
TOTAL_TIMEOUTS = The total number of times a process encountered a
timeout while waiting for an event. When a process begins to wait
for an event, it specifies a timeout period after which the
operating system should wake it up if the event has not yet
transpired. For example, when an Oracle process issues an I/O
request to read a block from a data file (the db file sequential
read wait event), the process sets a timeout of one second.
Usually the I/O request will complete in less than one second and
no timeout will occur. But if the read should take longer than one
second for whatever reason, a timeout will occur and the process
will wake up. The process might do some minor housekeeping, but it
will likely just begin another timeout period of one second and
continue waiting for the same event.
TIME_WAITED and AVERAGE_WAIT show the cumulative (sum) and average
time spent by processes waiting for this event, in centiseconds.
Multiply these figures by 100 in order to get the wait time in
seconds. These two columns will show as zero if timed statistics
are not enabled.
TIME_WAITED_MICRO is the same as TIME_WAITED, except that the time
is in microseconds. Multiply this figure by 1000000 in order to
get the wait time in seconds.
Consider the following query from v$system_event:
set linesize 180Since instance startup, processes on this system have waited a total of 286.57 seconds while reading single data file blocks from disk, and over 1,596 seconds (26 minutes) while writing redo to the online redo logs. A huge amount of time has been spent waiting on the smon timer and SQL*Net message from client events, but these are both idle wait events so we don't worry about them. (The SMON process spends a lot of time sleeping between consecutive checks of the system, and many dedicated server processes spend a lot of their time waiting for the application to submit a SQL statement for processing.)
select substr(event,1,40) event, total_waits, total_timeouts, 100*time_waited Time_Waited_Sec, 100*average_wait Average_Wait_Sec
FROM v$system_event
WHERE event IN ('SQL*Net message from client', 'smon timer', 'db file sequential read', 'log file parallel write');
EVENT TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED_SEC AVERAGE_WAIT_SEC
---------------------------------------- ----------- -------------- --------------- ----------------
log file parallel write 768 0 1596.92 60
db file sequential read 5190 0 286.57 72
smon timer 15 8 1306738.37 1605427
SQL*Net message from client 266 0 16189800 60864
The V$SESSION_EVENT View
The v$session_event view is a lot like the v$system_event view,
except that it shows separate rows of information for each Oracle
process. As with v$system_event, event names do not appear in this
view if the process has not waited for them at least once. Also,
when an Oracle process terminates (as in the case of when a user
logs off the database) all of the rows in v$session_event for that
process permanently disappear. The v$session_event view has the
following columns:
Name Null? Type
----------------------------------------- -------- -------------
SID NUMBER
EVENT VARCHAR2(64)
TOTAL_WAITS NUMBER
TOTAL_TIMEOUTS NUMBER
TIME_WAITED NUMBER
AVERAGE_WAIT NUMBER
MAX_WAIT NUMBER
TIME_WAITED_MICRO NUMBER
EVENT_ID NUMBER
WAIT_CLASS_ID NUMBER
WAIT_CLASS# NUMBER
WAIT_CLASS VARCHAR2(64)
SID = Session ID. You can query v$session in order to determine
the SID of the session whose wait events you want to investigate
EVENT = The name of the wait event, e.g. "library cache lock"
TOTAL_WAITS = total number of times this session has waited
TOTAL_TIMEOUTS = total no. of times timeouts occurred for this
TIME_WAITED = the total time (in 100th of sec) waited
AVERAGE_WAIT = the average wait per wait
MAX_WAIT = indicates the maximum amount of time the process had to
wait for the event. Like TIME_WAITED and AVERAGE_WAIT, the unit of
measure is centiseconds and will display as zero if timed
statistics are not enabled
TIME_WAITED_MICRO = same as time_waited; but in micro seconds
EVENT_ID = the event ID of the event
WAIT_CLASS_ID = the class of the waits
WAIT_CLASS#
WAIT_CLASS
Note = V$EVENT_NAME has the event details joined on EVENT#
column
Consider the following query which displays all wait event information for the current SQL*Plus session:
SELECT event, total_waits, time_waited_micro, max_wait
FROM v$session_event
WHERE SID = (SELECT sid FROM v$session WHERE audsid = USERENV ('sessionid'));
EVENT TOTAL_WAITS TIME_WAITED_MICRO MAX_WAIT
------------------------------ ----------- ----------------- ----------
log file sync 1 19629 2
db file sequential read 3 26128 1
db file scattered read 678 1154632 8
SQL*Net message to client 76 352 0
SQL*Net more data to client 1 63 0
SQL*Net message from client 75 1118656279 26930
SQL*Net break/reset to client 4 22281 2
You can see that the Oracle process serving this session has spent 1.180760 seconds waiting for disk I/O. Although there have been 76 instances where the process waited for the networking software to allow it to send a message to the client (the SQL*Plus program), each of these waits was shorter than the 0.01 second resolution of the MAX_WAIT column in v$session_event. (All 76 waits combined added up to only 0.000352 seconds.) Far and away, the Oracle process has spent the vast majority of its time (over 18 minutes) waiting for a SQL statement to be entered at the SQL*Plus prompt.
The V$SESSION_WAIT View
The v$session_wait view shows one row for each Oracle process. The
row indicates the name of the wait event and additional parameters
that provide further information about exactly what the process is
waiting for (or information about the most recent wait event if
the process is not currently waiting). While the v$system_event
and v$session_event views show cumulative wait event information,
the v$session_wait view shows information as of the present moment
only. The v$session_wait view has the following columns:
Name Null? TypeSID - Session ID.
----------------------------------------- -------- ----------------
SID NUMBER
SEQ# NUMBER
EVENT VARCHAR2(64)
P1TEXT VARCHAR2(64)
P1 NUMBER
P1RAW RAW(8)
P2TEXT VARCHAR2(64)
P2 NUMBER
P2RAW RAW(8)
P3TEXT VARCHAR2(64)
P3 NUMBER
P3RAW RAW(8)
WAIT_CLASS_ID NUMBER
WAIT_CLASS# NUMBER
WAIT_CLASS VARCHAR2(64)
WAIT_TIME NUMBER
SECONDS_IN_WAIT NUMBER
STATE VARCHAR2(19)
WAIT_TIME_MICRO NUMBER
TIME_REMAINING_MICRO NUMBER
TIME_SINCE_LAST_WAIT_MICRO NUMBER
The following query shows the parameters associated with the db file scattered read wait event:
SELECT *
FROM v$event_name
WHERE name = 'db file scattered read';
EVENT# NAME PARAMETER1 PARAMETER2 PARAMETER3
---------- ---------------------- ------------ ----------- -----------
188 db file scattered read file# block# blocks
This tells us that when a process is waiting for a multi-block read from disk to complete (as in the case of a full table scan where the data blocks were not already in the buffer cache), we can see the file from which the blocks are being read as well as the starting block and number of blocks.
The following query was run while a session was performing a full table scan:
set linesize 32000
SELECT sid,seq#,substr(event,1,35) event, p1text, p1, p2text, p2, p3text, p3, wait_time, seconds_in_wait, state
FROM v$session_wait WHERE sid = 442;
SID SEQ# EVENT
---------- ---------- ------------------------------
P1TEXT P1 P1RAW
------------------------------ ---------- --------
P2TEXT P2 P2RAW
------------------------------ ---------- --------
P3TEXT P3 P3RAW WAIT_TIME SECONDS_IN_WAIT
------------------------------ ---------- -------- ---------- ---------------
STATE
-------------------
442 303 db file scattered read
file# 17 00000011
block# 2721 00000AA1
blocks 8 00000008 -1 0
WAITED SHORT TIME
You can see that the process was not waiting at the moment this
query was run, but its last wait had been for an I/O request to
read eight blocks from file 17 starting at block 2721. That I/O
request had completed in less than 0.01 second. (Note the -1 in
the WAIT_TIME column when the STATE is WAITED SHORT TIME.) Why did
Oracle choose to read eight blocks at a time? Because the
db_file_multiblock_read_count instance parameter was set to eight.
For most wait events this view is sufficient, but it is hardly a
robust tuning tool for at least two important reasons:
* The view is a snapshot of the present. When
the waits cease to exist, the history of those waits experienced
by the session earlier disappears too, making after-effect
diagnosis difficult. V$SESSION_EVENT provides cumulative but not
very detailed data.
* V$SESSION_WAIT contains information only
about wait events; for all other relevant information such as the
userid and terminal you have to join it with the view V$SESSION.
The V$SESSION View
Oracle provides an interface to check what these values are .
useful work, idle time and waits.
The information is available in V$SESSION
- EVENT = shows what the session is/was stuck on
- SECONDS_IN_WAIT = shows the waits right now
- WAIT_TIME = shows the last wait time
- STATE - shows what is the session doing now
-
WAITING. The session is waiting on that event right now
- The amount of time
it has been waiting so far is shown under SECONDS_IN_WAIT
- WAITED
KNOWN TIME. The session waited for some time on that event, but
not just now
- The amount of time
it had waited is shown under WAIT_TIME
- WAITED
SHORT TIME. The session waited for some time on that event, but it
was too short to be recorded
- WAIT_TIME shows -1
Wait Time Accounting
Value of STATE ---> WAITING = check SECONDS_IN_WAIT
---> WAITED KNOWN TIME = check WAIT_TIME
---> WAITED SHORT TIME = WAIT_TIME is -1
set linesize 200
set pagesize 100
select sid, substr(event,1,40) Event, state, wait_time,
seconds_in_wait
from v$session ;
SID
EVENT
STATE
WAIT_TIME SECONDS_IN_WAIT
---------- ----------------------------------------
------------------- ---------- ---------------
1 rdbms ipc
message
WAITING
0
1
2 DIAG idle
wait
WAITING
0
1
3 rdbms ipc
message
WAITING
0
2
4 rdbms ipc
message
WAITING
0
1
5 Streams AQ:
qmn coordinator idle wait
WAITING
0
27
7 jobq slave
wait
WAITING
0
0
10 Streams AQ:
waiting for time management
WAITING
0
727
63 smon
timer
WAITING
0
275
64 DIAG idle
wait
WAITING
0
1
65 rdbms ipc
message
WAITING
0
2
66 rdbms ipc
message
WAITING
0
2
68 Space Manager:
slave idle
wait
WAITING
0
2
125 pmon
timer
WAITING
0
0
126 rdbms ipc
message
WAITING
0
0
127 rdbms ipc
message
WAITING
0
1426
128 rdbms ipc
message
WAITING
0
1
130 SQL*Net message from
client
WAITED KNOWN
TIME
1
0
187 VKTM Logical Idle
Wait
WAITING
0
5089
188 rdbms ipc
message
WAITING
0
2
189 rdbms ipc
message
WAITING
0
1
190 rdbms ipc
message
WAITING
0
1
191 jobq slave
wait
WAITING
0
0
194 rdbms ipc
message
WAITING
0
1
196 Streams AQ: qmn slave
idle wait
WAITING
0
27
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. We can find out who is holding the lock
very quickly:
SELECT sid, blocking_session, username, blocking_session_status status
FROM v$session
WHERE blocking_session_status = 'VALID';
SID BLOCKING_SESSION USERNAME STATUS
--- ---------------- -------- -----------
154 157 TSUTTON VALID
If we combine this with the wait event information available in v$session, we see:
SELECT sid, blocking_session, username, event, seconds_in_wait siw
FROM v$session
WHERE blocking_session_status = 'VALID';
SID BLOCKING_SESSION USERNAME EVENT SIW
--- ---------------- -------- ------------------------------ ---
154 157 TSUTTON enq: TX - row lock contention 318
The V$EVENT_NAME View
The v$event_name view shows reference information rather
than up-to-the-moment information about instance performance. This
view shows one row for each wait event known to the Oracle kernel.
Associated with each wait event are up to three
parameters-additional pieces of information that provide more
detail about a wait situation. This view displays the definition
of P(n) columns from V$SESSION_WAIT and can be joined on the NAME
column.
The v$event_name view has the following columns:
Name Null? Type
----------------------------------------- -------- -------------
EVENT# NUMBER
EVENT_ID NUMBER
NAME VARCHAR2(64)
PARAMETER1 VARCHAR2(64)
PARAMETER2 VARCHAR2(64)
PARAMETER3 VARCHAR2(64)
WAIT_CLASS_ID NUMBER
WAIT_CLASS# NUMBER
WAIT_CLASS VARCHAR2(64)
EVENT# = Number of the wait event.
NAME = Name of the event.
PARAMETER1 = Description of the value for P1.
PARAMETER2 = Description of the value for P2.
PARAMETER3 = Description of the value for P3.
WAIT_CLASS_ID = ID of the wait class
WAIT_CLASS# = Number of the class.
WAIT_CLASS = The name of the wait class (Idle, Network, System
I/O, etc.)
The v$system_event and v$session_event views show cumulative
information about past waits in summary form, leaving out
parameter information from each individual wait.
As we will see in the next sections, wait event parameters come
into play in the v$session_wait view and wait event trace files.
The V$SESSION_WAIT_HISTORY View
The v$session_wait_history view, helps by showing the last
ten wait events each session has experienced.
The columns in v$session_wait_history are:
DESC v$session_wait_history
Name Null? Type
----------------------------------------- -------- ----------------------------
SID NUMBER
SEQ# NUMBER
EVENT# NUMBER
EVENT VARCHAR2(64)
P1TEXT VARCHAR2(64)
P1 NUMBER
P2TEXT VARCHAR2(64)
P2 NUMBER
P3TEXT VARCHAR2(64)
P3 NUMBER
WAIT_TIME NUMBER
WAIT_COUNT NUMBER
As an example, the following query shows the ten most recent wait events for a session:
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. 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.SELECT sid, seq#, event, wait_time, p1, p2, p3
FROM v$session_wait_history
WHERE sid = 154
ORDER BY seq#;
SID SEQ# EVENT WAIT_TIME P1 P2 P3
--- ---- ------------------------ ---------- ------ ------ ------
154 1 db file sequential read 28 4 3547 1
154 2 log buffer space 18 0 0 0
154 3 log buffer space 36 0 0 0
154 4 db file sequential read 0 4 3559 1
154 5 db file sequential read 0 4 1272 1
154 6 db file sequential read 0 4 3555 1
154 7 log buffer space 9 0 0 0
154 8 db file sequential read 0 4 3551 1
154 9 db file sequential read 6 4 1268 1
154 10 log buffer space 8 0 0 0
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 table2
WHERE ...
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 V$EVENT_HISTOGRAM View
The columns of v$event_histogram are:
SQL> DESCRIBE v$event_histogram
Name Null? Type
----------------------------------------- -------- ----------------------------
EVENT# NUMBER
EVENT VARCHAR2(64)
WAIT_TIME_MILLI NUMBER
WAIT_COUNT NUMBER
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:
SELECT event, total_waits, time_waited, average_wait
FROM v$system_event
WHERE event = 'enq: TX - row lock contention';
EVENT TOTAL_WAITS TIME_WAITED AVERAGE_WAIT
----------------------------- ----------- ----------- ------------
enq: TX - row lock contention 17218 2101966 122
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, we can look at v$event_histogram for a more complete picture:
SELECT event, wait_time_milli, wait_count
FROM v$event_histogram
WHERE event = 'enq: TX - row lock contention';
EVENT WAIT_TIME_MILLI WAIT_COUNT
----------------------------- --------------- ----------
enq: TX - row lock contention 1 833
enq: TX - row lock contention 2 635
enq: TX - row lock contention 4 372
enq: TX - row lock contention 8 395
enq: TX - row lock contention 16 781
enq: TX - row lock contention 32 3729
enq: TX - row lock contention 64 3050
enq: TX - row lock contention 128 410
enq: TX - row lock contention 256 47
enq: TX - row lock contention 512 46
enq: TX - row lock contention 1024 37
enq: TX - row lock contention 2048 3
enq: TX - row lock contention 4096 6880
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 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:
SELECT wait_class, time_waited
FROM v$system_wait_class
ORDER BY time_waited DESC;
WAIT_CLASS TIME_WAITED
------------- -----------
Idle 777450022
System I/O 1261584
User I/O 116667
Configuration 116481
Application 72301
Other 12432
Commit 3496
Concurrency 319
Network 1
SELECT wait_class, time_waited
FROM v$session_wait_class
WHERE sid = 154
ORDER BY time_waited DESC;
WAIT_CLASS TIME_WAITED
------------- -----------
Idle 612453
User I/O 1500
Configuration 28
Commit 11
Other 0
Application 0
Network 0
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_snap;
CREATE TABLE swc_snap AS
SELECT wait_class, total_waits, time_waited
FROM v$system_wait_class;
And then, at time T2 a while later, get a summary of waits between T1 and T2:
SELECT a.wait_class, (a.time_waited - b.time_waited) tm_waited
FROM v$system_wait_class a, swc_snap b
WHERE a.wait_class = b.wait_class
AND a.total_waits > NVL (b.total_waits, 0)
ORDER BY tm_waited DESC;
WAIT_CLASS TM_WAITED
--------------- ----------
Idle 255767
Application 171
System I/O 156
User I/O 44
Other 21
Commit 13
Network 1
The v$session_wait_history view 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.
The 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> DESC v$active_session_history
Name Null? Type
----------------------------------------- -------- ----------------------------
SAMPLE_ID NUMBER
SAMPLE_TIME TIMESTAMP(3)
SESSION_ID NUMBER
SESSION_SERIAL# NUMBER
USER_ID NUMBER
SQL_ID VARCHAR2(13)
SQL_CHILD_NUMBER NUMBER
SQL_PLAN_HASH_VALUE NUMBER
SQL_OPCODE NUMBER
SERVICE_HASH NUMBER
SESSION_TYPE VARCHAR2(10)
SESSION_STATE VARCHAR2(7)
QC_SESSION_ID NUMBER
QC_INSTANCE_ID NUMBER
EVENT VARCHAR2(64)
EVENT_ID NUMBER
EVENT# NUMBER
SEQ# NUMBER
P1 NUMBER
P2 NUMBER
P3 NUMBER
WAIT_TIME NUMBER
TIME_WAITED NUMBER
CURRENT_OBJ# NUMBER
CURRENT_FILE# NUMBER
CURRENT_BLOCK# NUMBER
PROGRAM VARCHAR2(48)
MODULE VARCHAR2(48)
ACTION VARCHAR2(32)
CLIENT_ID 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 AWR 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:
SELECT DECODE (session_state, 'WAITING', event, NULL) event,
session_state, COUNT(*), SUM (time_waited) time_waited
FROM v$active_session_history
WHERE module = 'ARXENV'
AND sample_time > SYSDATE - (2/24)
GROUP BY DECODE (session_state, 'WAITING', event, NULL), session_state;
EVENT SESSION_STATE COUNT(*) TIME_WAITED
------------------------------ ------------- -------- -----------
ON CPU 124 0
log file sync WAITING 2 52686
db file scattered read WAITING 2 28254
db file sequential read WAITING 1 6059
control file sequential read WAITING 1 9206
SQL*Net break/reset to client WAITING 1 9140
enq: TX - row lock contention WAITING 922 930864016
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 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(AWR)
Another significant facility relevant to the wait event interface it’s 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 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 such as time model statistics (which we will discuss in the next section). As an aside, 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:
SELECT snap_id, substr(begin_interval_time,1,25) Begin_Interval, substr(end_interval_time,1,25) End_Interval
FROM (SELECT snap_id, begin_interval_time, end_interval_time
FROM dba_hist_snapshot
ORDER BY end_interval_time DESC)
WHERE 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, 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.
Oracle has a 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:
DESC v$sys_time_model
Name Null? Type
---------------------------------------- -------- ---------------------------
STAT_ID NUMBER
STAT_NAME VARCHAR2(64)
VALUE NUMBER
DESC v$sess_time_model
Name Null? Type
---------------------------------------- -------- ---------------------------
SID NUMBER
STAT_ID NUMBER
STAT_NAME VARCHAR2(64)
VALUE NUMBER
A sample query from v$sys_time_model shows the following:
SELECT stat_name, value / 1000000 seconds
FROM v$sys_time_model
ORDER BY seconds DESC;
STAT_NAME SECONDS
------------------------------------------------ ----------
DB time 80970.190
sql execute elapsed time 75057.271
DB CPU 44448.628
background elapsed time 29333.160
PL/SQL execution elapsed time 8824.538
background cpu time 5170.311
parse time elapsed 1270.147
hard parse elapsed time 838.068
PL/SQL compilation elapsed time 176.731
sequence load elapsed time 112.334
connection management call elapsed time 44.644
failed parse elapsed time 11.946
hard parse (sharing criteria) elapsed time 5.579
hard parse (bind mismatch) elapsed time 4.610
failed parse (out of shared memory) elapsed time 0.000
Java execution elapsed time 0.000
inbound PL/SQL rpc elapsed time 0.000
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 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
Wait Event Activity (SYSTEM EVENT 10046)
DBA's should be familiar with the SQL trace facility built into
Oracle.
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.
By using the commands below, you can enable SQL trace for your
session:
Using the TOP
Unix command or the v$session view you can check the
SID and SERIAL# number of the session to monitor.
select
sid, serial#, substr(terminal,1,10) terminal,
substr(program,1,40) program
from
v$session
where
terminal in('OCR04','IMGSVR')
-- where username = 'FRAUDGUARD';;
Then, you
activate the trace by using the package dbms_monitor. 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> DESC dbms_monitorIf 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:
...
PROCEDURE SESSION_TRACE_DISABLE
Argument Name Type In/Out Default?
------------------------------ ----------------------- ------ --------
SESSION_ID BINARY_INTEGER IN DEFAULT
SERIAL_NUM BINARY_INTEGER IN DEFAULT
PROCEDURE SESSION_TRACE_ENABLE
Argument Name Type In/Out Default?
------------------------------ ----------------------- ------ --------
SESSION_ID BINARY_INTEGER IN DEFAULT
SERIAL_NUM BINARY_INTEGER IN DEFAULT
WAITS BOOLEAN IN DEFAULT
BINDS BOOLEAN IN DEFAULT
ALTER SESSION SET events '10046 trace name context forever, level 12';
EXECUTE dbms_monitor.session_trace_enable (waits=>TRUE, binds=>TRUE);
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.
With dbms_monitor, 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_id174837492748');
...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:
EXECUTE dbms_monitor.client_id_trace_enable ('session_id174837492748', 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_id174837492748
In this way the dbms_monitor package and trcsess utility 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.
Example using SID and SERIAL
TURN
ON:
exec
dbms_monitor.session_trace_enable(&SID,
&SERIAL, waits=>
true, binds=> true)
/* code to be traced
executes during this time window */
TURN OFF:
exec exec
dbms_monitor.session_trace_disable(&SID,
&SERIAL)
Example
using Service or Module:
BEGIN
-->Enable/Disable
Client Identifier Trace.
DBMS_MONITOR.client_id_trace_enable
(client_id
=> ‘my_id’);
DBMS_MONITOR.client_id_trace_disable
(client_id
=> ‘my_id’);
-->Enable/Disable
Service, Module and Action Trace.
DBMS_MONITOR.serv_mod_act_trace_enable
(service_name=>'my_service');
DBMS_MONITOR.serv_mod_act_trace_enable
(service_name=>'my_service',
module_name=>'my_module');
DBMS_MONITOR.serv_mod_act_trace_enable
(service_name=>'my_service',module_name=>‘my_module’,action_name=>'INSERT');
DBMS_MONITOR.serv_mod_act_trace_disable
(service_name=>'my_service',module_name=>'my_module',action_name
=>'INSERT');
-->Enable/Disable
Session Trace .
DBMS_MONITOR.session_trace_enable;
DBMS_MONITOR.session_trace_enable(session_id
=>
12, serial_num => 1011);
DBMS_MONITOR.session_trace_disable(session_id
=>
12, serial_num => 1011);
END;
/
With the DBMS_MONITOR package, Oracle offers a fully supported
means of activating and deactivating diagnostic data collection
for a specific business action (or actions) you want to trace.
When SQL trace is enabled for a session, the Oracle process
writes detailed trace information (including timing data if timed
statistics are enabled) to a trace file in a directory specified
by the user_dump_dest instance parameter. These trace files are
plain text files and human readable, but rather tedious and
repetitive. You can optionally run trace files through a processor
such as TKPROF instead of looking at them directly.
Oracle has the ability to direct a process to include additional
information in the trace file, including wait event information.
In earlier releases of Oracle, we activated the wait event tracing
facility by setting debug event 10046. Debug event 10046 still
works in Oracle 9i, but recent releases of Oracle include a PL/SQL
package built-in that gives a more friendly means for activating
wait event tracing.
Setting debug events allows a DBA to instruct an Oracle instance
to take on a special, atypical behavior. Debug events can be used,
for example, to cause Oracle to write a system level dump file
whenever an ORA-0600 error occurs or skip over corrupted blocks in
a table when performing a full table scan. Most debug events
should never be set unless you are directed to do so by Oracle
Support. Some debug events can put your database at risk.
Debug event 10046 affects the amount of information written to
trace files. It is a very safe debug event, and one of the few
that you are allowed to set without special permission from Oracle
Support. Debug event 10046 can be set to the following values:
| Debug Event Setting | Effect |
| 10046 trace name context forever, level 1 | Enables ordinary SQL trace |
| 10046 trace name context forever, level 4 | Enables SQL trace with bind variable values included in trace file |
| 10046 trace name context forever, level 8 | Enables SQL trace with wait event information included in trace file |
| 10046 trace name context forever, level 12 | Equivalent of level 4 and level 8 together |
| 10046 trace name context off | Turns off tracing |
You can set the 10046 debug event to trace your session and collect wait event information in the trace file with either of the following commands:
EXECUTE SYS.DBMS_SUPPORT.START_TRACE
ALTER SESSION SET events '10046 trace name context forever, level 8';
You can set the 10046 debug event to trace another session on the
database with any of the following commands:
Find the session:
set linesize 150
column Name format a14
column SID format 9999
column PID format 99999
column TERM format a15
column OSUSER format a15
column Program format a15
column Stats format a10
column Logon_time format a20
select a.username Name, a.sid SID, a.serial#, b.spid PID,
SUBSTR(A.TERMINAL,1,9)
TERM, SUBSTR(A.OSUSER,1,9)
OSUSER,
substr(a.program,1,10)
Program, a.status
Status,
to_char(a.logon_time,'MM/DD/YYYY
hh24:mi') Logon_time
from v$session a, v$process b
where a.paddr = b.addr
and a.serial#
<> '1'
and a.status =
'ACTIVE'
and a.username like
upper('%&user%') -- if you want to filter by username
order by a.logon_time;
Once you have the SID and SERIAL# of the session
you can use some Oracle supplied packages.
-- set timed
statistics at user session level if not set at system
level.
execute
sys.dbms_system.set_boo_param_in_session(&&SID,
&&SERIAL,'timed_statistics',true);
--set
max dump file size if not set at system level.
execute
sys.dbms_system.set_in_param_in_session(&&SID,
&&SERIAL, 'max_dump_file_size',10000000);
-- activate level
8 extended SQL tracing.
execute
sys.dbms_system.set_ev(&&SID, &&SERIAL,
10046, 8, ' ');
or
execute sys.dbms_support.start_trace_in_session (&&SID, &&SERIAL)
******* run all of your processing here *******
-- disables extended SQL tracing.
execute
sys.dbms_system.set_ev(&&SID, &&SERIAL,
10046, 0, ' ');
or
execute sys.dbms_support.stop_trace_in_session (&&SID,
&&SERIAL)
Calling DBMS_SUPPORT as shown
here is equivalent to activating debug event 10046 at level 8. You
may include optional additional parameters in the procedure call
to activate level 4 or 12. The DBMS_SUPPORT package is not
installed in the database by default. You need to run the
dbmssupp.sql script found in the rdbms/admin directory as SYS
before you can call DBMS_SUPPORT.
It should also be pointed out that the SET_EV procedure in the
DBMS_SYSTEM package is not officially supported by Oracle
Corporation-they prefer that you use DBMS_SUPPORT instead. The
reason is that DBMS_SYSTEM.SET_EV allows you to set any debug
event in any session. As mentioned above some debug events can
potentially be dangerous, and DBMS_SYSTEM.SET_EV lets you set such
events in any session.
Unlike timed statistics, tracing consumes a significant amount of
system resources. Therefore it is important to use the tracing
facility sparingly. Trace only the sessions you need to trace, and
only for as long as you need. Turn off tracing as soon as it is no
longer needed with any of the following commands:
EXECUTE SYS.DBMS_SUPPORT.STOP_TRACE
ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT OFF';
ALTER SESSION SET sql_trace = FALSE;
EXECUTE SYS.DBMS_SUPPORT.STOP_TRACE_IN_SESSION (sid, serial#)
oradebug setorapid [Oracle PID from v$process]
oradebug session_event 10046 trace name context forever, level 0
EXECUTE SYS.DBMS_SYSTEM.SET_EV (sid, serial#, 10046, 0, '')
When you set debug event 10046 to a level of 8 or 12 (or call
START_TRACE or START_TRACE_IN_SESSION in DBMS_SUPPORT), the Oracle
process will write a line into the trace file every time it
finishes waiting for an event. The line in the trace file will
contain almost the same information that would have appeared in
the v$session_wait view, but perhaps in a slightly less friendly
format. You can also see in the trace file which cursor (and
therefore which SQL statement) the wait event was associated with.
Here is an excerpt from a trace file generated by setting debug
event 10046 to level 12 on an Oracle 8i database:
=====================
PARSING IN CURSOR #1 len=80 dep=0 uid=502 oct=3 lid=502
tim=2293771931 hv=2293373707 ad='511dca20'
SELECT /*+ FULL */ SUM (LENGTH(notes))
FROM customer_calls
WHERE status = :x
END OF STMT
PARSE #1:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=0,tim=2293771931
BINDS #1:
bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=03 oacfl2=0
size=24 offset=0
bfp=09717724 bln=22 avl=02 flg=05
value=43
EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=2293771931
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=675562835 p2=1 p3=0
WAIT #1: nam='db file scattered read' ela= 3 p1=17 p2=923 p3=8
WAIT #1: nam='db file scattered read' ela= 1 p1=17 p2=931 p3=8
WAIT #1: nam='db file scattered read' ela= 2 p1=17 p2=939 p3=8
WAIT #1: nam='db file sequential read' ela= 0 p1=17 p2=947 p3=1
WAIT #1: nam='db file scattered read' ela= 3 p1=17 p2=1657 p3=8
WAIT #1: nam='db file scattered read' ela= 1 p1=17 p2=1665 p3=8
WAIT #1: nam='db file scattered read' ela= 2 p1=17 p2=1673 p3=8
WAIT #1: nam='db file scattered read' ela= 0 p1=17 p2=1681 p3=8
WAIT #1: nam='db file scattered read' ela= 3 p1=17 p2=1761 p3=8
WAIT #1: nam='db file scattered read' ela= 1 p1=17 p2=1769 p3=8
WAIT #1: nam='db file scattered read' ela= 1 p1=17 p2=1777 p3=8
WAIT #1: nam='db file scattered read' ela= 0 p1=17 p2=1785 p3=8
WAIT #1: nam='db file scattered read' ela= 2 p1=17 p2=1841 p3=8
WAIT #1: nam='db file scattered read' ela= 1 p1=17 p2=1849 p3=8
The "ela=" figures indicate the duration of the wait. In trace
files generated by Oracle 8i and earlier, the elapsed time is
shown in centiseconds. Beginning in Oracle 9i, the elapsed time is
shown in microseconds.
You can see that when the session executed the query, there was a
wait shorter than one centisecond for a message to be sent to the
client, followed by a bunch of waits for I/O requests against file
17. Most of the I/O requests were multi-block reads, reading eight
blocks at a time while performing a full table scan of the
CUSTOMER_CALLS table.
You can probably imagine how large and overwhelming trace files
can get when anything but a trivial application is traced. This is
why Oracle provides the TKPROF utility. TKPROF takes a trace file
as input and generates a nicely formatted, easy to read report.
Unfortunately, the TKPROF that comes with Oracle 8i and earlier
releases ignores wait event information written in the trace file.
To analyze the wait event information collected by a trace in an
Oracle 8i or earlier environment, you will need to either pore
through the trace file manually or write your own trace file
parser and formatter. (We've heard of people writing perl scripts
to do this, but we have never come across them.)
The TKPROF utility that comes with Oracle 9i is capable of
reporting wait event information summarized by distinct statement.
By default Oracle 9i TKPROF ignores wait event information in the
trace file as earlier releases did. However, if the "waits=yes"
command line argument is provided, a separate table of wait event
statistics will appear in the report for each distinct statement.
Here is a sample excerpt from a TKPROF report showing wait event
information:
********************************************************************************
SELECT A.customer_id, A.customer_name, COUNT (*) purchases,
MAX (B.transaction_date) last_purchase_date
FROM customers A, purchase_history B
WHERE B.customer_id = A.customer_id
GROUP BY A.customer_id, A.customer_name
ORDER BY A.customer_id
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.06 0.12 0 27 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1461 21.41 25.80 7801 5905 5 21893
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1463 21.47 25.93 7801 5932 5 21893
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 17
Rows Row Source Operation
------- ---------------------------------------------------
21893 SORT GROUP BY
1525494 HASH JOIN
31212 TABLE ACCESS FULL CUSTOMERS
1525494 INDEX FAST FULL SCAN PURCHASE_HISTORY_PK (object id 7824)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1461 0.00 0.00
db file sequential read 4 0.00 0.01
db file scattered read 750 0.07 2.25
direct path write 271 0.83 2.79
direct path read 254 0.00 0.01
SQL*Net message from client 1461 1.28 22.40
********************************************************************************
You can see that the query was parsed and executed once, and
there were 1461 fetches to read 21893 rows. The Oracle process
used 21.47 CPU seconds and 25.93 seconds of elapsed time to parse,
execute, and fetch the query. The elapsed time was greater than
the CPU time because the Oracle process had to wait on several
wait events. The listing at the bottom of the report shows the
process waited on network roundtrips to the client and reads and
writes to disk.
All of these waits seem to make sense: There was one network
roundtrip to the client for each fetch call, and it took SQL*Plus
a long time (over 22 seconds) to display the 21,893 rows of data
on my display. The db file sequential reads and db file scattered
reads resulted from the table access and index fast full scan. The
direct path writes and reads resulted from the hash join and sort
operations. If you add the CPU time of 21.47 seconds and the wait
times (5.06 seconds not including the SQL*Net message from client
waits) you come up with an elapsed time of 26.53 seconds. However,
the report shows the total elapsed time as 25.93 seconds. This is
a good example of the round-off error that is not unusual when
thousands of very short time intervals are added together.
In some situations you may not be able to identify exactly which
session to trace. This happens frequently when your database is
supporting a web application that has frequent short connections,
or an application server tier that maintains a pool of database
connections all logged on as the same Oracle user. You may have a
specific query you want to collect wait event information for, but
you may not know which session will be executing the query. One
way to deal with this situation is to trace all of the sessions
being started by your application for a brief period. This can be
done easily with the following SQL*Plus script:
SPOOL traceall.sql
SET HEADING OFF FEEDBACK OFF
SELECT 'EXECUTE SYS.dbms_system.set_ev (' || TO_CHAR (sid) ||
', ' || TO_CHAR (serial#) || ', 10046, 8, '''')'
FROM v$session
WHERE username = 'WEB_USER';
SPOOL OFF
SET FEEDBACK ON
@traceall.sql
This script will start wait event tracing on all sessions
connected to the database as the WEB_USER user. To stop tracing
simply change the 8 after the 10046 to a 0 and run the script
again. You should think about how many sessions this script will
trace and how that will affect server load before running on a
production system.
After you've traced a number of sessions, you can scan the trace
files for occurrences of a specific query with a command like the
following:
grep -n 1234567890 *.trc
Replace 1234567890 with the hash value or address of the
statement you are interested in. (You can get these values by
querying v$sql.) The output of the above grep command will tell
you which trace files the query appears in and on which lines. You
can then go to that point in the trace files and get detailed wait
event information.
Trace files are easiest to work with when you use a dedicated
server connection to the database. If you connect to the database
using Oracle's shared server architecture then different SQL
statements may be executed by different server processes. Each
server process writes to its own trace file. Thus the trace
information for the session can be spread over several trace
files.
Wait
Interface
In the latest versions of Oracle, the wait
interface has been radically redesigned to provide more
information with less DBA intervention. In this article, we will
explore those new features and see how they aid us in the
diagnosis of performance problems. For most of the performance
problems, you will get an extended analysis from Automatic
Database Diagnostic Manager (ADDM), but for immediate problems
not yet captured by ADDM, the wait interface provides valuable
data for diagnosis.
Enhanced Session Waits
The first enhancement involves V$SESSION_WAIT itself. It's best
explained through an example. Let's
imagine
that your user has complained that her session is hanging. You
found out the session's SID and selected the record from the
view V$SESSION_WAIT for that SID. The output is shown below.
SID : 269Note the columns shown in bold; of those columns, WAIT_CLASS_ID, WAIT_CLASS#, and WAIT_CLASS are new in 10g. The column WAIT_CLASS indicates the type of the wait that must be either addressed as a valid wait event or dismissed as an idle one. In the above example, the wait class is shown as Application, meaning that it's a wait that requires your attention.
SEQ# : 56
EVENT : enq: TX - row lock contention
P1TEXT : name|mode
P1 : 1415053318
P1RAW : 54580006
P2TEXT : usn<<16 | slot
P2 : 327681
P2RAW : 00050001
P3TEXT : sequence
P3 : 43
P3RAW : 0000002B
WAIT_CLASS_ID : 4217450380
WAIT_CLASS# : 1
WAIT_CLASS : Application
WAIT_TIME : -2
SECONDS_IN_WAIT : 0
STATE : WAITED UNKNOWN TIME
select wait_class, event, sid, state, wait_time, seconds_in_waitHere is a sample output:
from v$session_wait
order by wait_class, event, sid
/
WAIT_CLASS EVENT SID STATE WAIT_TIME SECONDS_IN_WAITHere you can see that several events (such as Queue Monitor Wait and JobQueue Slave) are clearly classified as Idle events. You could eliminate them as nonblocking waits; however, sometimes these "idle" events can indicate an inherent problem. For example, the SQL*Net-related events may indicate high network latency, among other factors.
---------- -------------------- ---------- ------------------- ---------- ---------------
Application enq: TX - 269 WAITING 0 73
row lock contention
Idle Queue Monitor Wait 270 WAITING 0 40
Idle SQL*Net message from client 265 WAITING 0 73
Idle jobq slave wait 259 WAITING 0 8485
Idle pmon timer 280 WAITING 0 73
Idle rdbms ipc message 267 WAITING 0 184770
Idle wakeup time manager 268 WAITING 0 40
Network SQL*Net message to client 272 WAITED SHORT TIME -1 0
EVENT# NUMBERThe columns are identical to those in V$SESSION_WAIT and display the same information, eliminating the need to look in that view. So, you need to check only one view for any sessions waiting for any event.
EVENT VARCHAR2(64)
P1TEXT VARCHAR2(64)
P1 NUMBER
P1RAW RAW(4)
P2TEXT VARCHAR2(64)
P2 NUMBER
P2RAW RAW(4)
P3TEXT VARCHAR2(64)
P3 NUMBER
P3RAW RAW(4)
WAIT_CLASS_ID NUMBER
WAIT_CLASS# NUMBER
WAIT_CLASS VARCHAR2(64)
WAIT_TIME NUMBER
SECONDS_IN_WAIT NUMBER
STATE VARCHAR2(19)
select BLOCKING_SESSION_STATUS, BLOCKING_SESSIONThere it is: the session with SID 265 is blocking the session 269. Could it be any easier?
from v$session
where sid = 269;
BLOCKING_SE BLOCKING_SESSION
----------- ----------------
VALID 265
select * from v$session_wait_class where sid = 269;The output comes back as:
SID SERIAL# WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS TOTAL_WAITS TIME_WAITEDNote the copious information here about the session's waits. Now you know that the session has waited 873 times for a total of 261,537 centi-seconds for application-related waits, 15 times in network-related events, and so on. Extending the same principle, you can see the system-wide statistics for wait classes with the following query. Again, the time is in centi-seconds.
---- ------- ------------- ----------- ------------- ----------- -----------
269 1106 4217450380 1 Application 873 261537
269 1106 3290255840 2 Configuration 4 4
269 1106 3386400367 5 Commit 1 0
269 1106 2723168908 6 Idle 15 148408
269 1106 2000153315 7 Network 15 0
269 1106 1740759767 8 User I/O 26 1
select * from v$system_wait_class;Most problems do not occur in isolation; they leave behind tell-tale clues that can be identified by patterns. The pattern can be seen from a historical view of the wait classes as follows.
WAIT_CLASS_ID WAIT_CLASS# WAIT_CLASS TOTAL_WAITS TIME_WAITED
------------- ----------- ------------- ----------- -----------
1893977003 0 Other 2483 18108
4217450380 1 Application 1352 386101
3290255840 2 Configuration 82 230
3875070507 4 Concurrency 80 395
3386400367 5 Commit 2625 1925
2723168908 6 Idle 645527 219397953
2000153315 7 Network 2125 2
1740759767 8 User I/O 5085 3006
4108307767 9 System I/O 127979 18623
select * from v$waitclassmetric;This view stores the statistics related to wait classes over the last minute.
select wait_class#, wait_class_id,Note the WAIT_CLASS_ID and related statistics. For the value 4217450380, we saw that the 2 sessions waited for this class in the last minute for a total of 5 times and for 1,499 centi-seconds. But what is this wait class? You can get that information from V$SYSTEM_WAIT_CLASS as shown above—it's the class Application. Note the column named DBTIME_IN_WAIT, a very useful one, it shows the time spent inside the database.
average_waiter_count "awc", dbtime_in_wait,
time_waited, wait_count
from v$waitclassmetric;
WAIT_CLASS# WAIT_CLASS_ID AWC DBTIME_IN_WAIT TIME_WAITED WAIT_COUNT
----------- ------------- ---- -------------- ----------- ----------
0 1893977003 0 0 0 1
1 4217450380 2 90 1499 5
2 3290255840 0 0 4 3
3 4166625743 0 0 0 0
4 3875070507 0 0 0 1
5 3386400367 0 0 0 0
6 2723168908 59 0 351541 264
7 2000153315 0 0 0 25
8 1740759767 0 0 0 0
9 4108307767 0 0 8 100
10 2396326234 0 0 0 0
11 3871361733 0 0 0 0
select event, wait_time, wait_countWhen the sessions become inactive or disconnected, the records disappear from that view. However, the history of these waits is maintained in AWR tables for further analysis. The view that shows the session waits from the AWR is V$ACTIVE_SESSION_HISTORY.
from v$session_wait_history
where sid = 265;
EVENT WAIT_TIME WAIT_COUNT
------------------------------ ---------- ----------
log file switch completion 2 1
log file switch completion 1 1
log file switch completion 0 1
SQL*Net message from client 49852 1
SQL*Net message to client 0 1
enq: TX - row lock contention 28 1
SQL*Net message from client 131 1
SQL*Net message to client 0 1
log file sync 2 1
log buffer space 1 1
select sess.username, sess.sid, se.event, se.total_waits, se.total_timeouts, se.time_waited/100 time_waited, se.average_wait
from v$session_event se, v$session sess
where event like '%buffer busy%'
and sess.sid = se.sid
and sess.username is not null
and se.total_waits > 10000
order by username, sid;
TIME AVG
TOTAL TOTAL WAITED WAIT
USER SID EVENT WAITS TIMEOUTS SECONDS 100ths
----- ---- -------------------- ------ -------- -------- ------
MYAPP 25 buffer busy waits 12407 1 21 0
62 buffer busy waits 27117 0 43 0
77 buffer busy waits 11096 2 14 0
85 buffer busy waits 54095 1 56 0
87 buffer busy waits 44871 0 51 0
Even more interesting is the information provided by the v$session_wait view. This view provides data on waits as they happen. Oracle publishes the information needed to decode the wait data provided in the P1, P2, and P3 columns in the Oracle Reference Manual.
Using our example of buffer busy waits, you can determine on which objects in the database the waits are occurring. Example 2 shows the output from v$session_wait when buffer busy waits are encountered:
USERNAME EVENT SID P1 P2
---------- ----------------- --- -- ---
JKSTILL buffer busy waits 162 4 279
Example 2: Buffer busy wait in v$session_wait.
Using the information provided in the Oracle Reference Manual (refer to the references at the end of this article) you can use the information in the P1 and P2 columns to determine what object and block is causing the buffer busy waits. The SQL script in Listing 2 will determine which file, segment, and segment type in which the hot block is located.
col
cfileid
new_value ufileid noprint
col cblockid new_value ublockid noprint
prompt
File
ID:
set term off feed off
select '&1' cfileid from dual;
set
feed
on term on
prompt Block ID:
set term off feed off
select '&2' cblockid from dual;
set feed on term on
select file_name "FILE FOR BLOCK"
from dba_data_files
where file_id = &ufileid;
col
segment_name
format a30
col segment_type format a15
select
segment_name,
segment_type
from dba_extents
where file_id = &ufileid
and &ublockid between block_id and block_id + blocks
- 1;
undef 1 2
Listing 2: In which table is the hot block?
The output for this query is shown in Example 3. From this, you can see the file referred to by P1, but more importantly, you can see that that buffer busy waits on occurring on table X:
FILE FOR BLOCK
----------------------------------------
/u01/app/oracle/oradata/ts02/users01.dbf
SEGMENT_NAME SEGMENT_TYPE
------------------------------ ---------------
X TABLE
Example 3: Hotblock search results.
The ability to diagnose in real time what is causing waits in the database appears to be a valuable diagnostic tool, and in fact, it is. The problem with capturing these in real time, though, is that they often happen much too fast for you to catch by running a SQL query. You may see some of the waits, but may miss many as well. Databases work on a clock that measures time in microseconds or less, while your fingers can only rerun a query a few times per second.
Many enterprising folks have written tools to capture the data from v$session_wait by rerunning the query frequently inside a loop. This will still miss many wait events and leave you with incomplete data, in addition to placing an extra load on your already busy database.
This is where Oracle 10g comes to the rescue. Now, in addition to the venerable wait interface that was introduced in Oracle 7, Oracle 10g includes Active Session History, or ASH.
By
querying ASH views, you can now capture not only the current
wait event, but the 10 most recent wait events for each session
in the database. While this does not eliminate missing events —
more than 10 events can easily occur between executions of the
query — it does provide a much better picture of what wait
events are occurring per session.
By querying the v$session_wait_history view, it becomes apparent
that buffer busy waits on table X are not the only events on
which the session is waiting (Example 4 tells the tale). The SQL
can be seen in Listing 3:
select s.sid , s.username username , e.event event , e.p1 , e.p2
--, e.wait_time
from v$session s, v$session_wait_history e
where s.username is not null
and s.sid = e.sid
order by s.sid, s.username, e.seq#;
Listing 3: Display session wait history.
TIME
SID USERNAME EVENT P1 P2 WAITED
--- -------- ------------------------------ ---------- ------ ------
144 JKSTILL latch: cache buffers chains 1533685692 116 15
JKSTILL latch: cache buffers chains 1533685692 116 15
...
162 JKSTILL latch: cache buffers chains 1533685692 116 15
JKSTILL latch: cache buffers chains 1533685692 116 15
JKSTILL latch: cache buffers chains 1533685692 116 0
JKSTILL latch: cache buffers chains 1533685692 116 15
JKSTILL latch: cache buffers chains 1533685692 116 15
JKSTILL buffer busy waits 2 11820 15
JKSTILL latch: cache buffers chains 1533685692 116 0
JKSTILL latch: cache buffers chains 1533685692 116 15
JKSTILL buffer busy waits 4 279 15
JKSTILL latch: cache buffers chains 1533685692 116 15
Example 4: Session wait history.
The output from v$session_wait_history makes it clear that buffer busy waits on table X are not the only problem here. There are also buffer busy waits on the UNDO segment, shown as P1=2 and P2=11820 in the output. Also seen are many more waits on the cache buffers chain latch than buffer busy waits, which account for more of the wait time than do the buffers busy waits.
So far, so good. Querying only the v$session_wait view, I could determine that waits were occurring on the table X. Using the v$session_wait_history view, it became obvious that this was only part of the problem.
Carrying it further, the v$active_session_history view is the ASH counterpart to the v$session_event view. By querying it, a more detailed picture emerges. Listing 4 details the SQL used to create the output of Example 5:
col
sample_time
format a9
col event_name format a25
col p1 format 9999999999
col p2 format 99999
col p3 format 99999
col wait_time format 99999 head 'WAIT|TIME'
col time_waited format 999999 head 'TIME|WAITED'
set
pagesize
60
set linesize 120
select to_char(h.sample_time,'mi:ss.ff3') sample_time, e.name event_name, h.p1, h.p2
--, h.p3
, h.session_state, h.wait_time, time_waited
from v$active_session_history h, v$event_name e
where session_id = 162
and session_serial# = 4743
and e.event_id = h.event_id
and h.sample_time between sysdate - ( 55/1440 ) and sysdate
order by h.seq#;
Listing 4: Query v$active_session_history.
SAMPLE_TI EVENT_NAME P1 P2 SESSION TIME
--------- ------------------------- ----------- ------ ------- ------
25:22.012 db file sequential read 2 10459 ON CPU 15
25:23.032 db file sequential read 2 15130 ON CPU 18
25:24.052 db file sequential read 2 12535 ON CPU 23
25:25.072 latch: cache buffers chai 1533685692 116 WAITING 0
ns
...
25:58.782 buffer busy waits 4 279 WAITING 0
...
26:22.272 db file sequential read 2 794 ON CPU 22
26:23.292 latch: cache buffers chai 1533685692 116 WAITING 0
ns
...
26:43.722 db file sequential read 2 1041 ON CPU 22
Example 5: v$active_session_history output.
Example 5 provides a more complete picture of the waits that have occurred than was ever possible using the old-style wait interface that was available in Oracle versions 7 — 9i.
As a diagnostic tool, it is far more capable than the previous wait interface. I’ve only scratched the surface here in showing what information can be acquired with ASH views.
Query examples