Wait Events   April 11, 2008

 

extracted from Perform Without Waiting
By Arup Nanda http://www.oracle.com/technology/oramag/oracle/04-jul/o44tech_perf.html

Wait states are very important in diagnosing performance bottle necks.  Oracle Enterprise Manager (OEM) offers several indicators as dash board. In this article, techniques to show wait information is going to be given using SQL*Plus rather than OEM

select sid, username, event, blocking_session,
   seconds_in_wait, wait_time
from v$session where state in ('WAITING')
and wait_class != 'Idle';

One can find what SQL statement is being executed using V$SQL

select sid, sql_text
from v$session s, v$sql q
where sid in (254,270)
and (
   q.sql_id = s.sql_id or
   q.sql_id = s.prev_sql_id);

One can also find to which category the waits belong on

select wait_class_id, wait_class,
   total_waits, time_waited
from v$session_wait_class
where sid = 270;

WAIT_CLASS_ID      WAIT_CLASS          TOTAL_WAITS      TIME_WAITED
-------------    ---------------       -----------      -----------
   1893977003      Other                     16331           44107
   4217450380      Application               17760          281654
   3290255840      Configuration               834            2794
   3875070507      Concurrency                1599           96981
   3386400367      Commit                    13865            4616
   2723168908      Idle                     513024       103732677
   2000153315      Network                  254534             379
   1740759767      User I/O                  32709           53182
   4108307767      System I/O               103019            9921

Note:  Time is in Hundredth of a second (1/100)

One can also drill down

select event, total_waits, time_waited
from v$system_event e, v$event_name n
where n.event_id = e.event_id
and wait_class_id = 4217450380
Oracle 10g provides a new view, V$EVENT_HISTOGRAM, that shows the wait time periods and how often sessions have waited for a specific time period. He issues the following against V$EVENT_HISTOGRAM: 
select wait_time_milli bucket, wait_count
 from v$event_histogram
 where event =
    'enq: TX - row lock contention';

The output looks like this: 

    BUCKET     WAIT_COUNT
-----------    ----------
         1         	  252
         2          	   0
         4          	   0
         8          	   0
        16          	   1	
        32          	   0
        64           	  4
       128          	  52
       256         	  706
       512        	   392
      1024         	   18
      2048         	    7
      4096        	   843
In the Time Model interface of Oracle Database 10g, One can easily view details of time spent by a session in various activities. He issues the following against the V$SESS_TIME_MODEL view:

 

select stat_name, value
from v$sess_time_model 
where sid = 355;
 
STAT_NAME                                                         VALUE	
---------------------------------------------------          ----------
DB time                                                       878239757
DB CPU                                                        835688063
background elapsed time                                               0
background cpu time                                                   0
sequence load elapsed time                                            0
parse time elapsed                                            503996336
hard parse elapsed time                                       360750582
sql execute elapsed time                                      878088366
connection management call elapsed time                            7207
failed parse elapsed time                                        134516
failed parse (out of shared memory) elapsed time                      0
hard parse (sharing criteria) elapsed time                            0
hard parse (bind mismatch) elapsed time                               0
PL/SQL execution elapsed time                                   6294618
inbound PL/SQL rpc elapsed time                                       0
PL/SQL compilation elapsed time                                  126221
Java execution elapsed time                                           0
 
 
 
select * from v$osstat;
Output from V$OSSTAT view 
STAT_NAME                                   VALUE        OSSTAT_ID
--------------------------            -----------       ----------	
NUM_CPUS                                       1                0
IDLE_TICKS                              51025805                1	
BUSY_TICKS                               2389857                2
USER_TICKS                               1947618                3	
SYS_TICKS                                 439736                4
NICE_TICKS                                  2503                6
AVG_IDLE_TICKS                          51025805                7
AVG_BUSY_TICKS                           2389857                8
AVG_USER_TICKS                           1947618                9
AVG_SYS_TICKS                             439736               10
AVG_NICE_TICKS                              2503               12
RSRC_MGR_CPU_WAIT_TIME                         0               14
IN_BYTES                             16053940224             1000
OUT_BYTES                            96638402560             1001
AVG_IN_BYTES                         16053940224             1004
AVG_OUT_BYTES                        96638402560             1005

 

select sample_time, event, wait_time
from v$active_session_history
where session_id = 271
and session_serial# = 5;

SAMPLE_TIME                   EVENT                              WAIT_TIME	
--------------------------    ---------------------------        ---------
22-FEB-04 03.17.23.028 PM     latch: library cache                 14384	
22-FEB-04 03.17.24.048 PM     latch: library cache                 14384
22-FEB-04 03.17.25.068 PM     log file switch completion           17498	
22-FEB-04 03.17.26.088 PM     log file switch completion           17498	
22-FEB-04 03.17.27.108 PM     log buffer space                     11834
22-FEB-04 03.17.28.128 PM     log buffer space                     11834
22-FEB-04 03.17.29.148 PM     log buffer space                     11834
22-FEB-04 03.17.30.168 PM     log buffer space                     11834
22-FEB-04 03.17.31.188 PM     log buffer space                     11834

 

select sql_text, application_wait_time
from v$sql
where sql_id in (
  select sql_id
  from v$active_session_history
  where sample_time = 
   '22-FEB-04 03.17.31.188 PM'
  and session_id = 271
  and session_serial# = 5
);

SQL_TEXT                                                             APPLICATION_WAIT_TIME
------------------------------------------------------------------   ---------------------
update accounts set balance = balance - 750 where account_no = 333                     950
update accounts set balance = balance - 845 where account_no = 451                     457
update accounts set balance = balance - 434 where account_no = 239                    1235

The purged ASH data can be seen in the DBA_HIST_ACTIVE_SESSION_HIST view, enabling John to see the wait events of a past session. The data in the AWR is purged by default after seven days.