Waits in a SQL

VarugheseJanuary 30, 2015September 17, 2016

When a SQL runs, the time it takes to run is basically come from the CPU time needed plus the time for waits.

The following SQL looks into gv$active_session_history and finds the time the SQL spends on each wait event or CPU

The Script

--
--
-- sqlwaits.sql
-- Parameters - none
--
-- Purpose: Identify all wait events related to a particular sql from gv$active_session_history
-- 
set verify on
set echo on
set lines 250
set head on
set tab off

col event format a30 wrap
col PCT format 99.99

  SELECT sql_id,
         event,
         event_cnt,
         ROUND ( (event_cnt / 60), 2) event_time,
         round((event_cnt/tot_cnt) * 100,2) PCT,
         execs_for_event,
         total_execs,
         ROUND ( (tot_cnt / 60), 2) tot_time_mins,
         ROUND (tot_cnt / total_execs) avg_secs_per_exec
    FROM (SELECT DISTINCT sql_id
                          , NVL (event, 'ON CPU') event
                          , COUNT (DISTINCT sql_id || sql_exec_id || sql_exec_start) OVER (PARTITION BY event) execs_for_event
                          , COUNT (*) OVER (PARTITION BY event) event_cnt
                          , COUNT (*) OVER () tot_cnt
                          , COUNT (DISTINCT sql_id || sql_exec_id || sql_exec_start) OVER () total_execs
            FROM gv$active_session_history
           WHERE sql_id = '&1')
ORDER BY pct DESC
/

CLEAR COLUMNS

A brief explanation of the columns is given below:

SQL_ID — SQL ID
EVENT — Name of the wait event
EVENT_CNT — Count of the event
EVENT_TIME — Total time spent on the event
PCT — Percentage
EXECS_FOR_EVENT — How many executions contributed to this event
TOTAL_EXECS –Total number executions of the SQL
TOT_TIME_MINS — Total time from all executions
AVG_SECS_PER_EXEC — Average time per single execution

Sample Run

Enter value for 1: 9ht3rsgxfjks0
old  17:            WHERE sql_id = '&1')
new  17:            WHERE sql_id = '9ht3rsgxfjks0')

SQL_ID        EVENT                           EVENT_CNT EVENT_TIME    PCT EXECS_FOR_EVENT TOTAL_EXECS TOT_TIME_MINS AVG_SECS_PER_EXEC
------------- ------------------------------ ---------- ---------- ------ --------------- ----------- ------------- -----------------
9ht3rsgxfjks0 ON CPU                              48116     801.93  99.24             270         311         808.1               156
9ht3rsgxfjks0 db file sequential read               144        2.4    .30              53         311         808.1               156
9ht3rsgxfjks0 enq: SQ - contention                   85       1.42    .18              17         311         808.1               156
9ht3rsgxfjks0 gc current grant 2-way                 54         .9    .11              16         311         808.1               156
9ht3rsgxfjks0 gc current multi block request         45        .75    .09              22         311         808.1               156
9ht3rsgxfjks0 log file sync                           8        .13    .02               5         311         808.1               156
9ht3rsgxfjks0 gc current grant busy                   6         .1    .01               4         311         808.1               156
9ht3rsgxfjks0 gc buffer busy acquire                  3        .05    .01               1         311         808.1               156
9ht3rsgxfjks0 enq: TX - contention                    6         .1    .01               4         311         808.1               156
9ht3rsgxfjks0 row cache lock                          4        .07    .01               4         311         808.1               156
9ht3rsgxfjks0 library cache pin                       4        .07    .01               4         311         808.1               156
9ht3rsgxfjks0 undo segment extension                  2        .03    .00               2         311         808.1               156
9ht3rsgxfjks0 library cache: mutex X                  2        .03    .00               2         311         808.1               156
9ht3rsgxfjks0 gc current block 2-way                  1        .02    .00               1         311         808.1               156
9ht3rsgxfjks0 gc current block 3-way                  2        .03    .00               1         311         808.1               156
9ht3rsgxfjks0 enq: FB - contention                    1        .02    .00               1         311         808.1               156
9ht3rsgxfjks0 log file switch completion              2        .03    .00               2         311         808.1               156
9ht3rsgxfjks0 gc current grant congested              1        .02    .00               1         311         808.1               156

Conclusion

Looking at the output, we can easly tell what contributed to the time spent on the SQL. In the example above it is mostly CPU. Other waits are insignificant.

db file sequential read is index reads wich took only less than 1 percent. Also enq: SQ – contention is relate to sequence that is also less than 1 %

Here we need to reduce the CPU time to improve this SQL.