Oracle Database - Mining Active Session History (ASH) for Plan/SQL Execution Wait Events

In this blog I am going to discuss about mining ASH for wait events for a specific sql session or specific sql or specific plan hash value execution wait events.

This can be really powerful in cases like - 

1. when sql_monitoring report is no longer available,

2. or you want to tune a particular plan and you want to know at what plan_line it is taking more time

3. you want to tune a plan and want to know at what line it is taking time with what kind of wait event.

There are many other use cases but the above are summary of what can be done. 

Now I will quickly jump onto the sql part.

First SQL is to find out the Time taken by SQL on each plan line per the options

set lines 500 pages 500
col object_name for a25

SELECT plan_hash_value,
id line,
operation,
options,
object_name,
sum(10)
FROM dba_hist_active_sess_history a,
dba_hist_sql_plan b
WHERE a.sql_plan_hash_value = b.plan_hash_value
AND a.sql_id = b.sql_id
AND a.sql_plan_line_id = b.id
AND a.sql_id = 'ah9xc371174p7'
AND a.session_id = 446
AND a.session_serial# = 26701
GROUP BY plan_hash_value, id, operation, options, object_name
ORDER by 1,2;

 

There is a sum 10 option because dba_hist_active_sess_history has a sample size of 10 seconds

 Now Lets see to get this output from V$active_session_history, remember the sample size of V$ASH is 1 second.

SELECT plan_hash_value,
id line,
operation,
options,
object_name,
sum(1)
FROM V$active_session_history a,
dba_hist_sql_plan b
WHERE a.sql_plan_hash_value = b.plan_hash_value
AND a.sql_id = b.sql_id
AND a.sql_plan_line_id = b.id
AND a.sql_id = 'ah9xc371174p7'
AND a.session_id = 6769
AND a.session_serial# = 38229
GROUP BY plan_hash_value, id, operation, options, object_name
ORDER by 1,2;

 

 I have truncated the object names for obvious reasons in both. 

The key thing to notice here is that you have the time for each plan_line and the type of operation. 

Now the next thing is to find out within the operation / plan line what was the actual wait event i.e was it really I/O or CPU or direct path read etc. 

 

select ss.sql_id,
ss.sql_plan_line_id,
case SESSION_STATE when 'WAITING' then event
else SESSION_STATE end TIME_CATEGORY,
(SUM(10)) seconds,
round(RATIO_TO_REPORT(count(*)) OVER () * 100 ,2) pct_wait
from dba_hist_active_sess_history ss
WHERE ss.sql_id = 'ah9xc371174p7'
AND ss.session_id = 446
AND ss.session_serial# = 26701
group by ss.sql_id,ss.sql_plan_line_id,session_state,event
order by seconds;

SQL_ID        SQL_PLAN_LINE_ID TIME_CATEGORY                SECONDS   PCT_WAIT

------------- ---------------- ------------------------- ---------- ----------

ah9xc371174p7                5 db file sequential read           20        .22

ah9xc371174p7                5 db file parallel read             30        .33

ah9xc371174p7                1 ON CPU                            50        .55

ah9xc371174p7                2 ON CPU                            60        .65

ah9xc371174p7                5 ON CPU                            80        .87

ah9xc371174p7                6 ON CPU                          1130      12.32

ah9xc371174p7                6 db file parallel read           2760       30.1

ah9xc371174p7                6 db file sequential read         5040      54.96

 (In case output above is not formatted properly  due to font / browser limitations - see below output) 

Now lets see this output from V$Active Session History. 

select ss.sql_id,
ss.sql_plan_line_id,
case SESSION_STATE when 'WAITING' then event
else SESSION_STATE end TIME_CATEGORY,
(SUM(1)) seconds,
round(RATIO_TO_REPORT(count(*)) OVER () * 100 ,2) pct_wait
from  V$active_session_history ss
WHERE ss.sql_id = 'ah9xc371174p7'
AND ss.session_id = 6769
AND ss.session_serial# = 38229
group by ss.sql_id,ss.sql_plan_line_id,session_state,event
order by seconds;  

 The key thing here is to find on what step the sql took more time and take an informed decision if we want to tune that step / access path or wait_event. 

You can apply filters in V$ASH / DB_HIST_ASH to find details for different plans as a summary without a specific session or set of sessions, totally up to you.