Active Session History query analyze

In this article i´m trying to make a query performance analysis based on ASH (active session history) views. Sometimes you need an historical point of view of a query due to this query is increasing its executions times, or query changed its execution plan. First step is to select top queries your database has:

select * from (
 select
   SQL_ID ,
   sum(decode(session_state,'ON CPU',1,0)) as CPU,
   sum(decode(session_state,'WAITING',1,0)) - sum(decode(session_state,'WAITING', decode(wait_class, 'User I/O',1,0),0)) as WAIT,
   sum(decode(session_state,'WAITING', decode(wait_class, 'User I/O',1,0),0)) as IO,
   sum(decode(session_state,'ON CPU',1,1)) as TOTAL
 from v$active_session_history
 where SQL_ID is not NULL
 group by sql_id
 order by sum(decode(session_state,'ON CPU',1,1))   desc
 )
where rownum <11;

for example, in my database:

SQL> select * from (
        select
                 SQL_ID ,
                 sum(decode(session_state,'ON CPU',1,0)) as CPU,
                 sum(decode(session_state,'WAITING',1,0)) - sum(decode(session_state,'WAITING', decode(wait_class, 'User I/O',1,0),0)) as WAIT,
                 sum(decode(session_state,'WAITING', decode(wait_class, 'User I/O',1,0),0)) as IO,
                 sum(decode(session_state,'ON CPU',1,1)) as TOTAL
        from v$active_session_history
        where SQL_ID is not NULL
        group by sql_id
        order by sum(decode(session_state,'ON CPU',1,1))   desc
        )
where rownum <11  2    3    4    5    6    7    8    9   10   11   12   13
 14  ;


SQL_ID               CPU       WAIT         IO      TOTAL
------------- ---------- ---------- ---------- ----------
bfsr168437nxh       7684          4          0       7688
cgq23v8v46pc4       4166          1          1       4168
6ay80wrrk0a5w        370          1       3590       3961
aqr2xb2xb8ubd       3541         51        296       3888
6xb9akamb4d8y       3404          7        223       3634
dg707t66s9vdm       2248          0          3       2251
1p901pshdg7cm       1672          1          2       1675
65b1z38ah62ym       1644          6          1       1651
49nxnk5r6rtvp        261        116        769       1146
4atb5w5206uv8        896          4         18        918

10 rows selected.

, now you can extract detailed information about one specifiq query (6ay80wrrk0a5w) over the time:

SQL> set linesize 200
set pages 1200
col snap_id for 999999
col BEGIN_INTERVAL_TIME for a23
col INST for 9
col END_INTERVAL_TIME for a23
col INSTANCE_NUMBER for 99
col OPTIMIZER_COST for 9999999999
col PLSEXEC_TIME_TOTAL for 999
col STARTUP_TIME for a22
col PARSING_SCHEMA_ID for 9999999999999
select st.snap_id, st.INSTANCE_NUMBER as INST, st.sql_id , st.OPTIMIZER_COST, sn.BEGIN_INTERVAL_TIME,  st.PLAN_HASH_VALUE, 
round( st.CPU_TIME_DELTA/1000000,3) as CPU, round(st.IOWAIT_DELTA/1000000,3) as IO_Wait, 
round(st.ELAPSED_TIME_DELTA/1000000,3) as elapsed_time, round(st.BUFFER_GETS_DELTA/1000000,3) as buffer_gets_M,  
round(st.BUFFER_GETS_TOTAL/1000000,3) as BUFFER_GETS_TOTAL_M, round(st.ELAPSED_TIME_TOTAL/1000000,3) as ELAPSED_TIME_TOTAL , round(st.FETCHES_DELTA,3) as Num_executions ,
case (ELAPSED_TIME_TOTAL-ELAPSED_TIME_DELTA) when 0 then 'start' end from dba_hist_sqlstat st, dba_hist_snapshot sn where st.snap_id=sn.snap_id and  st.INSTANCE_NUMBER=sn.INSTANCE_NUMBER and
st.sql_id in  (('6ay80wrrk0a5w')) order by  st.INSTANCE_NUMBER , st.SQL_ID, st.snap_id;

SNAP_ID INST SQL_ID        OPTIMIZER_COST BEGIN_INTERVAL_TIME     PLAN_HASH_VALUE        CPU    IO_WAIT ELAPSED_TIME BUFFER_GETS_M BUFFER_GETS_TOTAL_M ELAPSED_TIME_TOTAL NUM_EXECUTIONS CASE(
------- ---- ------------- -------------- ----------------------- --------------- ---------- ---------- ------------ ------------- ------------------- ------------------ -------------- -----
..........................................................................................................................................................................................
  27424    2 6ay80wrrk0a5w         109003 02/10/17 07:00:03,680        2312224021      52,73    633,975      693,788         5,663              54,742           6841,237              3
  27425    2 6ay80wrrk0a5w         109003 02/10/17 08:00:04,284        2312224021      16,81    192,876      211,463         1,888              56,629             7052,7              1
  27426    2 6ay80wrrk0a5w         109003 02/10/17 09:00:20,329        2312224021      69,82    811,263      888,119         7,551              37,757           4643,288              4
  27428    2 6ay80wrrk0a5w         109003 02/10/17 11:00:31,557        2312224021      52,08    529,009      582,818         5,665              43,422           5226,105              3
  27429    2 6ay80wrrk0a5w         109003 02/10/17 12:00:07,466        2312224021      86,39    994,928     1091,989         9,443              52,865           6318,094              5
  27430    2 6ay80wrrk0a5w         109003 02/10/17 13:00:16,549        2312224021      68,71    735,868      809,001         7,556              60,421           7127,096              4
  27431    2 6ay80wrrk0a5w         109003 02/10/17 14:00:38,667        2312224021       54,3    814,064      875,536         5,668              66,088           8002,632              3
  27432    2 6ay80wrrk0a5w         109003 02/10/17 15:00:55,247        2312224021       51,6    513,301      567,309         5,669              71,757            8569,94              3
  27433    2 6ay80wrrk0a5w         109003 02/10/17 16:00:10,971        2312224021      53,23    615,376      677,552         5,669              77,426           9247,493              3
  27434    2 6ay80wrrk0a5w         109003 02/10/17 17:00:27,011        2312224021       81,7    804,726      890,834          9,45              86,876          10138,327              5
  27435    2 6ay80wrrk0a5w         109003 02/10/17 18:00:05,693        2312224021      48,27    495,847      546,151          5,67              92,546          10684,478              3
  27436    2 6ay80wrrk0a5w         109003 02/10/17 19:00:27,338        2312224021      48,34    460,252      510,583          5,67              98,216          11195,061              3
  27437    2 6ay80wrrk0a5w         109003 02/10/17 20:00:13,181        2312224021      49,17    594,867      648,913         5,671             103,887          11843,974              3
  27438    2 6ay80wrrk0a5w         109003 02/10/17 21:00:11,573        2312224021      70,38   1443,535     1529,812         7,561             111,448          13373,786              4
  27439    2 6ay80wrrk0a5w         109003 02/10/17 22:00:34,087        2312224021      50,49     524,91      577,766         5,671             117,119          13951,552              3
  27440    2 6ay80wrrk0a5w         109003 02/10/17 23:00:56,251        2312224021      67,14    829,702      894,198         7,561             124,681          14845,749              4
  27441    2 6ay80wrrk0a5w         109004 03/10/17 00:00:13,581        2312224021      49,89    465,617      514,887         5,671             130,352          15360,637              3
  27442    2 6ay80wrrk0a5w         109004 03/10/17 01:00:28,332        2312224021      67,74   1115,555     1196,639         7,561             137,913          16557,276              4
  27443    2 6ay80wrrk0a5w         109004 03/10/17 02:00:02,654        2312224021      49,13    731,209      788,044         5,671             143,584           17345,32              3
  27444    2 6ay80wrrk0a5w         109004 03/10/17 03:00:24,666        2312224021      50,63   1165,432     1226,946         5,671             149,256          18572,266              3
  27445    2 6ay80wrrk0a5w         109004 03/10/17 04:00:14,193        2312224021      32,13    404,745      439,826         3,781             153,036          19012,091              2
  27446    2 6ay80wrrk0a5w         109004 03/10/17 05:00:07,728        2312224021      47,65    455,244          505         5,671             158,708          19517,092              3
  27447    2 6ay80wrrk0a5w         109004 03/10/17 06:00:28,520        2312224021      47,82    400,151      448,488         5,671             164,379           19965,58              3
  27448    2 6ay80wrrk0a5w         109004 03/10/17 07:00:49,793        2312224021      32,79    287,931      320,692         3,781              52,932           6514,076              2
  27449    2 6ay80wrrk0a5w         109004 03/10/17 08:00:11,445        2312224021      50,27    638,077      692,226         5,668                58,6           7206,302              3

where CPU --> Cpu time between snaps IO_WAIT --> User I/O wait time between snaps NUM_EXECUTIONS --> Execution count of the query between snaps ELAPSED_TIME --> Time used by this cursor for parsing/executing/fetching between snaps in miliseconds (1 second = 1000 milesecond) And as we can see below, IO_WAIT event is causing most of the waits in this query. For snap_id=27444 IO_WAIT represents 1165,432 milisecond of 1226,946 of total elapsed time. So between 3/10/2017 03:00 and 03/10/17 04:00 there were 3 executions of this query, and most waiting event was IO_WAIT . With the below query we can see in detail waiting events between to snapshot pairs:

select  INSTANCE_NUMBER, WAIT_CLASS,  sum(TIME_WAITED), sum(TEMP_SPACE_ALLOCATED)
from dba_hist_active_sess_history   where SQL_ID in ('6ay80wrrk0a5w') and SNAP_ID  between 27447 and 27448
group by INSTANCE_NUMBER, WAIT_CLASS;

INSTANCE_NUMBER WAIT_CLASS      SUM(TIME_WAITED) SUM(TEMP_SPACE_ALLOCATED)
--------------- --------------- ---------------- -------------------------
              2 User I/O                   70244
              1 User I/O                   56186
              1                                0
              2                                0

So, with this query we can confirm our first analysis. Now, doing this we can obtain execution plan of the query:

SQL> select plan_table_output from table(dbms_xplan.display_cursor('6ay80wrrk0a5w',null,'Typical'));

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  6ay80wrrk0a5w, child number 1
-------------------------------------

Plan hash value: 2312224021

---------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name               | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                    |       |       |   109K(100)|          |
|   1 |  NESTED LOOPS                |                    |     1 |   513 |   109K  (1)| 00:21:49 |
|*  2 |   TABLE ACCESS FULL          | T2360              |     1 |    60 |   108K  (1)| 00:21:48 |
|*  3 |   TABLE ACCESS BY INDEX ROWID| T2356              |     1 |   453 |    12   (0)| 00:00:01 |
|*  4 |    INDEX RANGE SCAN          | I2356_1000000161_1 |    16 |       |     2   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------------


31 rows selected.

So we can see select statement last 21:49 minutes, and full table scan is 21:48. So we can work in two lines. 1 Try to avoid this full table scan in order to speed up this query. You can do that manually or with Automatic Sql Tuning
2 Try to speed up disk performance by partitioning this table, move it to memory (Oracle 11 and 12) or put this filesystem into faster disks.