All about Wait
Events[Automatic Workload
Repository](http://www.pafumi.net/Wait_Events.html#Automatic_Workload_RepositoryAWR)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.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:- DB File Scattered Read.
That generally happens during a or . 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 longIf 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.- 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.- 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.- 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.- 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.- 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.- 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.- 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.- 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.- 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.- 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.- 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. - 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. - 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 - 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.- 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. - 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.- 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- direct Path writes:
- direct Path reads / direct path writes:
- write complete waits:
- direct path read temp or direct path write temp:
- Undo segment extension:
- wait for a undo record:
- Control File Parallel Write
- Control File Sequential Read
- DB File Parallel Write:
- Library Cache load lock
- log file sequential read
Idle events are usually not
very interesting from a tuning standpoint
|
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
|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: - Time spent using the CPU
- Time spent waiting for a CPU to become available
- Time spent waiting for requested memory to be swapped back in
to physical memoryThis 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. 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: - ALTER SYSTEM SET timed_statistics = TRUE;
- ALTER SESSION SET timed_statistics = TRUE;
You may enable timed statistics at the instance level on the next
and all subsequent instance restarts by adding the following line
to the instance parameter file:
timed_statistics = trueIn practice, the overhead of collecting timed statistics is
extremely small, so by default this parameter is set to TRUE.Wait Event Views
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 V$SYSTEM_EVENT
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 180
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
V$SESSION_EVENT
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. V$SESSION_WAIT
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? Type
—————————————– ——– —————-
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 readfile# 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 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: 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 V$SYSTEM_WAIT_CLASS and
V$SESSION_WAIT_CLASS ViewThe 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
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_waitedFROM 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 0log 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.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 PMJust 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. 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_monitor
…
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
TURNON:
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. un TKPROF to translate
the trace file created before into a readable output file. This
step can optionally create a SQL script that stores the statistics
in the database. tkprof trace_file
file_name sys=no explain=user/passwd@connectionWhen 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: | |
| |
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;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=8The "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 *.trcReplace 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. 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'simagine
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 : 269
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** Note the columns shown in bold; of those
columns, , , and
are new in 10_g_. The column 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 , meaning that it's a wait
that requires your attention.This column
highlights those few records that could prove most relevant for
your tuning. For example, you could use a query like the
following to get the wait sessions for events. select wait_class, event, sid, state, wait_time, seconds_in_waitfrom v$session_wait
order by wait_class, event, sid
/
Here is a sample output: WAIT_CLASS EVENT SID STATE WAIT_TIME SECONDS_IN_WAIT
———- ——————– ———- ——————- ———- —————
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
Here you can see that several events (such as
and ) are
clearly classified as 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. The other important thing to note is the value of
as -2. Some platforms such as Windows do not support a fast timing
mechanism. If the initialization parameter
isn't set on those platforms, accurate timing statistics can't be
determined. In such cases, a very large number is shown in this
column in Oracle9_i_, which clouds the issue further. In 10_g_,
the value -2 indicates this condition—the platform does not
support a fast timing mechanism and is
not set. (For the remainder of the article, we will assume the
presence of a fast timing mechanism.) SessionsShow
Waits TooRemember the long-standing requirement
to join V$SESSION_WAIT to V$SESSION in order to get the other
details about the session? Well, that's history. In 10_g_,
the view V$SESSION also shows the waits shown by V$SESSION_WAIT.
Here are the additional columns of the view V$SESSION that show
the wait event for which the session is currently waiting. EVENT# NUMBEREVENT 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)
The 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.Let's revisit
the original problem: The session with SID 269 was waiting for
the event , indicating
that it is waiting for a lock held by another session. To
diagnose the problem, you must identify that other session. But
how do you do that? In
Oracle9_i_ and below, you might have to write a complicated
(and expensive) query to get the SID of the lock holding session.
In 10_g_, all you have to do is issue the following query:
select BLOCKING_SESSION_STATUS, BLOCKING_SESSIONfrom v$session
where sid = 269;
BLOCKING_SE BLOCKING_SESSION
———– —————-
VALID 265
There it is: the session with SID 265 is
blocking the session 269. Could it be any easier? How
Many Waits? The user is still in your cubicle because her question is still
not answered satisfactorily. Why has her session taken this long
to complete? You can find out by issuing: 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_WAITED
—- ——- ————- ———– ————- ———– ———–
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
Note 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. select * from v$system_wait_class;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
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. select * from v$waitclassmetric;This view stores the statistics related to
wait classes over the last minute. select wait_class#, wait_class_id, 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 0Note the and related
statistics. For the value , 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 . Note the column named , a
very useful one, it shows the time spent inside the database. EveryoneLeaves
a Trail Finally the user leaves and you breathe a sigh of relief. But you
may still want to get to the bottom of what different waits
contributed to the problem in her session in the first place.
Sure, you can easily get the answer by querying V$SESSION_WAIT—but
unfortunately, the wait events are not present now and hence the
view does not have any records of them. What would you do? In 10_g_, a history of the session waits is maintained
automatically for the last 10 events of active sessions, available
through the view V$SESSION_WAIT_HISTORY. To find out these events,
you would simply issue: select event, wait_time, wait_countfrom 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
When 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._Example 1:
Buffer Busy Waits > 10000 in v$session_event.__Oracle
Reference Manual__Example 2:
Buffer busy wait in v$session_wait.__Oracle Reference Manual_
_Listing 2:
In which table is the hot block?__Example 3:
Hotblock search results.__g__g_
_Listing 3: Display session wait history._
_Example 4:
Session wait history.__Listing 4:
Query v$active_session_history.__Example 5:
v$active_session_history output._Query
examples What resource is currently in high demand?select
active_session_history.event,sum(active_session_history.wait_time
- active_session_history.time_waited)
ttl_wait_timefrom
v$active_session_history active_session_historywhere
active_session_history.sample_time between sysdate - 60/2880 and
sysdategroup by
active_session_history.eventorder by 2;
Wait
Event TTL_WAIT_TIME -------------SQL*Net message to
client 4null
event 5LGWR wait for redo
copy 161ksfd: async disk
IO 476direct path
read 30025latch: cache buffers
chains
33258direct path
write 93564log file sequential
read 178662db file sequential
read 458653log file
sync 612660control file single
write
1127626read by other
session 2024242db file parallel
write 2278618control file parallel
write
3091888enq: CF –
contention 4108238rdbms ipc
reply 4283877db file scattered
read 4357653class slave
wait 5123780control file sequential
read 6971659rdbms ipc
message 11899157jobq slave
wait 14732974log file parallel
write 15310721log buffer
space 21405250SQL*Net message from
client 26272575log file switch
completion
66115558enq: HW –
contention 100841479buffer busy
waits 114070065What
user is waiting the most?select sesion.sid, sesion.username,
sum(active_session_history.wait_time
+
active_session_history.time_waited) ttl_wait_timefrom
v$active_session_history active_session_history, v$session sesionwhere
active_session_history.sample_time between sysdate - 60/2880 and
sysdate and
active_session_history.session_id = sesion.sidgroup by sesion.sid,
sesion.usernameorder by 3;
SID
User TTL_WAIT_TIME—– ———- ————-
135
SCOTT
91167481149
SCOTT
107409491153
SCOTT
110796799What
SQL is currently using the most resources?select
active_session_history.user_id, dba_users.username,
sqlarea.sql_text,sum(active_session_history.wait_time
- active_session_history.time_waited) ttl_wait_time
from
v$active_session_history active_session_history, v$sqlarea
sqlarea, dba_userswhere
active_session_history.sample_time between sysdate - 60/2880 and
sysdate and
active_session_history.sql_id = sqlarea.sql_id and
active_session_history.user_id = dba_users.user_idgroup by
active_session_history.user_id,sqlarea.sql_text,
dba_users.usernameorder by 4;
USER_ID User
SQL_TEXT TTL_WAIT_TIME——- ——
-----------------------------------------------------
------------- 57
SCOTT insert into sys.sourcetable (select * from
sys.source$) 304169752What
object is currently causing the highest resource waits?set linesize 90
col object_name heading
'Object|Name' format a27 col c2 heading
'Object|Type' format a20 col c3 heading
'Event|Name' format a30 col c4 heading 'Total|Wait Time|(in secs)' format 999,999 select obj.object_name , obj.object_type c2, active_session_history.event
c3, round((sum(active_session_history.wait_time +
active_session_history.time_waited)/ 100),2) c4 from v$active_session_history
active_session_history, dba_objects obj where active_session_history.sample_time between
sysdate - 60/2880 and sysdate and active_session_history.current_obj# =
obj.object_id group by obj.object_name, obj.object_type,
active_session_history.event order by 4;OBJECT_NAME
OBJECT_TYPE Wait
Event TTL_WAIT_TIME————– ————
------------------------------ -------------SOURCE$ TABLE
ksfd: async disk
IO 23SOURCETABLE TABLE
ksfd: async disk
IO 453SOURCETABLE TABLE
latch: cache buffers
chains
33258SOURCETABLE TABLE
db file scattered
read 82593SOURCETABLE TABLE
db file sequential
read 111202SOURCETABLE TABLE
control file parallel
write
137237SOURCETABLE TABLE
read by other
session 165501SOURCETABLE TABLE
log file
sync 612660SOURCE$ TABLE
log buffer
space 932308SOURCETABLE TABLE
control file sequential
read 1428575SOURCE$ TABLE
log file switch
completion
1856281SOURCE$ TABLE
read by other
session 1858741SOURCE$ TABLE
db file scattered
read 4275060SOURCETABLE TABLE
rdbms ipc
reply 4283877SOURCETABLE TABLE
log buffer
space 14152000SOURCE$ TABLE
enq: HW -
contention 25483656SOURCETABLE TABLE
log file switch
completion
59228080SOURCETABLE TABLE
enq: HW -
contention 75357823SOURCETABLE TABLE
buffer busy
waits 114055403Getting the SQL
Full Code