By Alexander Bubernak
Collecting Real Time Wait Events
The scenario from my example below is taken at a time when
multiple users have called in complaining about performance for the past 10
minutes of running their application.
The examples here are just a brief overview of how to use
collected real time wait event data.
Note: Parameter timed_statistics must be set to true
to collect timing of wait events.
Let's create a table to store real time wait events for
session information.
/*
Author: Alex Bubernak
This will create
real_time_session_waits table
*/
drop table real_time_session_waits
/
create table real_time_session_waits
( snap_tm date not null,
seq# number not null,
sid number not null,
event varchar2(64) not null,
p1 number,
p2 number,
p3 number,
wait_time number,
seconds_in_wait number,
object_id number )
tablespace tools
/
Run the following anonymous SQL block to insert wait events
for a given time period. For our example, we will use a 30-second sampling.
SQL> @collect_rt_waits
SQL> Enter time is seconds to run: 30
collect_rt_waits.sql
/*
Author: Alex Bubernak
This script will select from v$session_wait and v$session to
insert real-time wait event statistics in user created table.
Inserts are run every second until run time is exceeded or
you can modify dbms_lock.sleep(n) to any time you prefer.
Remove truncate command to keep history.
Modify script to only collect waits for a single session if
necessary.
Instructions:
SQL> collect_rt_waits.sql
SQL> Enter time in seconds to run: 30
*/
accept tm prompt 'Enter time in seconds to run: '
variable tm_t number;
truncate table real_time_session_waits -- comment out to keep history
/
declare
iteration number;
start_time date;
begin
:tm_t := '&&tm';
select sysdate into start_time from dual;
iteration := 24*60*60/:tm_t;
while sysdate < start_time+1/iteration loop
insert into real_time_session_waits (SNAP_TM,
SEQ#,
SID,
EVENT,
P1,
P2,
P3,
WAIT_TIME,
SECONDS_IN_WAIT,
OBJECT_ID )
select sysdate,
a.seq#,
a.sid,
a.event,
a.p1,
a.p2,
a.p3,
a.wait_time,
a.seconds_in_wait,
b.row_wait_obj#
from v$session_wait a,
v$session b
where a.sid = b.sid
-- and a.sid = 'session id' -- only insert a single session
and a.event not in
('pmon timer',
'rdbms ipc message',
'smon timer',
'dispatcher timer',
'Null event',
'parallel query dequeue wait',
'parallel query idle wait - Slaves',
'pipe get',
'PL/SQL lock timer',
'slave wait',
'virtual circuit status',
'lock element cleanup',
'WMON goes to sleep'
);
dbms_lock.sleep(1); -- sleep for one second before checking and inserting next record.
-- Can take this out for more detail or change value for longer
-- runs.
end loop;
commit;
end;
/
Let's display wait event counts and time by session and for
our example filter idle events. Note: Remember what was said previously
about idle events.
wait_cnt_by_sess.sql
/*
Author: Alex Bubernak
Script displays wait event count and time for each sessions
completed wait event
*/
set linesize 150
col sid format 99999 heading "Session ID"
col event format a45 heading "Wait Event"
col cnt heading "Wait Count"
col wait heading "Wait time(cs)"
col pct format 999.99 heading "% of Time"
select sid,event, count(*) cnt, sum(wait_time) wait
from real_time_session_waits
where wait_time > 0 -- this will limit wait times from sessions that have completed event and are > 1 sc.
-- and sid = 81 -- change to limit by sid
-- filter out idle events
and event not in ('SQL*Net break/reset to client',
'SQL*Net message to client',
'SQL*Net message from client',
'SQL*Net more data to client')
group by sid,event
order by wait
/
Session ID Wait Event Wait Count Wait time(cs)
---------- --------------------------------- ---------- -------------
4 control file parallel write 1 0
82 free buffer waits 1 0
139 db file sequential read 14 1
105 latch free 15 1
81 buffer busy waits 1 1
48 db file sequential read 19 1
41 db file sequential read 28 2
88 latch free 18 2
132 db file sequential read 20 2
81 db file sequential read 19 11
2 db file parallel write 18 20
143 latch free 20 127
133 db file sequential read 9 1098
82 db file sequential read 10 1525
172 db file sequential read 10 1755
81 db file sequential read 20 2298
We see that session 81 waited 20 times for 'db file
sequential read' for almost 23 seconds of the 30 second sampling.
Now let's modify the script to filter for session 81.
Session ID Wait Event Wait Count Wait time(cs)
---------- --------------------------------- ---------- -------------
81 latch free 1 3
81 buffer busy waits 1 5
81 db file sequential read 20 2298
We can see three wait events with the most significant and largest
amount of time are for 'db file sequential read' for the 30-second timeframe.
The SQL statement involved should be analyzed to eliminate any unnecessary IOs,
possibly spread IO across multiple volumes, partition the object if possible,
etc.
From the above examples, we can see where the bottleneck in
the session is, for the given timeframe. In the above, you can join
REAL_TIME_SESSION_WAITS.OBJECT_ID with DBA_OBJECTS.DATA_OBJECT_ID to find the
object or objects involved. In this case the P(n) columns would also be able to
tell you what objects are involved when joined with DBA_EXTENTS.
SELECT owner, segment_type, segment_name
FROM dba_extents
WHERE file_id = 'P1 value'
AND 'P2 value' BETWEEN block_id AND block_id + blocks - 1;
We could also look at V$SESSION_EVENT for wait event
statistics for the life of the session.
select event,
total_waits,
time_waited
from v$session_event
where sid = 81
order by time_waited
/
EVENT TOTAL_WAITS TIME_WAITED
----------------------------------- ----------- -----------
buffer busy waits 15 0
wait list latch free 2 3
SQL*Net message to client 41715 5
db file parallel read 8 8
free buffer waits 3 41
direct path read 2001 47
log buffer space 7 110
log file sync 53 148
db file sequential read 98 5568
latch free 33361 6157
db file scattered read 63065 10374
SQL*Net message from client 41714 79457
As you can see 'db file sequential read' is shown as a less
significant wait event compared to the other three top events. This is not saying
that the other events should not be examined, but that the problem was most
noticeable to the users with a high 'db file sequential read' wait event time.
The above example only shows you a small piece of how to
collect and use real time wait events.
Summary
Real time wait events are an excellent way of troubleshooting
a problem as it is happening and are easier to setup and collect compared to 10046
event tracing. It does not have the accuracy or as much detail as the 10046
event, but can be a quick method to troubleshoot a problem as it is happening.
» 