Main | Yet another workaround for missing AVG() function for the Oracle interval type »

The Oracle Active Session History (ASH) - a real treasure trove


DISCLAIMER : For the use of Active Session History (ASH) you need have a license for Oracle Tuning Pack

When Oracle introduced the Active Session History (ASH) a new gate of tuning and monitoring options was opened.  Yes we had statspack, extended tracing and so on but all these tools were mssing a time(line) dimension. For example statspack reports and later AWR reports are flattened aggregations of numbers carefully to interpret as details are flushed as you always have only a look on an aggregated view of performance metrics.

Its like you are a photographer taking a long time exposure image from a busy street in the night. Yes you clearly can see where the most car took the road due to the traces of lights, but its almost impossible to describe a car accident in this kind of exposure. Also the longer the exposure time the lesser it gets meaningful. 
ASH is different, with the same camera you take a photo every second, and there you have it : you get a filming sequence instead of a long term exposure.

The ASH metrics are stored in only one table, it's like a large fact table with a lot of dimensions in it, to answer a lot of different questions. To be honest : you are beaten by the amount of information when you select it simply directly:


And there my problem started, usually I search in the internet for a meaningful SQL report but I did not find one which was both simple and expressive. So I was need to write an own one being inspired by the graphical reports of the Grid Control.

First some basic ideas behind any ASH report. There exist two kinds of Events

  • Waiting on a resource
  • being working on CPU which is indeed not a wait event and also originates in the session_state not in th event column

Waiting events itself can be grouped in

  • waiting for resources - means your process is faster then the resource you requested can deliver data on time, on typical example is waiting on I/O;
  • waiting for a lock to be released - you're doomed to wait until another lock holding sessions/process frees the lock. This is some kind of unproductive wait.

the report starts with a 15 minute window and sorts by Top-SQL with the largest amount of sample records - I call them simply Units. A Unit approximately is one second.

Now the fine thing which I appreciate much is that for the reported SQL all waiting events recorded are counted/aggregated into the Events column, with the wait event largest being the first one. Also with every listed event the number of samples/Units is provided. So you can easily identify on what mainly your SQL but also on what else it was waiting/working.

It's now my favourite SQL to see what is going on last 15 minutes.

The ASH records all events of an SQL independent on the final runtime so its not a monitoring table for long running SQL - instead you have to sort out shorter running SQL for Top-N Analyis.

Be aware of that your 15 minute window is moving, means a SQL with 100 Units after (you re-execute the report) a while it has only 70 Units further declining, which does not mean it accidentally started to wait less but you are fading out with the reported data until it disappears completely from the 15 minute window. 

So far so good, here it is with a sample output on a 2-Node RAC, the sql_text is not provided. 

SELECT Q2.Inst_Id, Q2.Sid, Q2.Sql_Id, Q2.Start_Time, Du.Username, Q2.Units, Q2.Events, Q2.Sql_Text
              ,(SELECT s.Sql_Text
                  FROM Gv$sql s
                 WHERE s.Inst_Id = Q1.Inst_Id
                   AND s.Sql_Id = Q1.Sql_Id
                   AND Rownum < 2) AS Sql_Text
          FROM (SELECT Qx.Inst_Id
                      ,Qx.Session_Id AS Sid
                      ,To_Char(MIN(Qx.Sql_Exec_Start), 'HH24:MI:SS') AS Start_Time
                      ,SUM(Qx.Num_Samples) AS Units
                      ,Listagg(Qx.Event || '(' || Qx.Num_Samples || ')', ', ') Within GROUP(ORDER BY Qx.Num_Samples DESC) AS Events
                  FROM (SELECT Ash.Inst_Id
                              ,MIN(Ash.Sql_Exec_Start) AS Sql_Exec_Start
                                   WHEN (Session_State = 'ON CPU') THEN
                               END AS Event
                              ,COUNT(*) AS Num_Samples
                          FROM Gv$active_Session_History Ash
                         WHERE Ash.Sample_Time > SYSDATE - INTERVAL '15' Minute
                         GROUP BY Ash.Inst_Id
                                      WHEN (Session_State = 'ON CPU') THEN
                                 ,Ash.Sql_Exec_Id) Qx
                 GROUP BY Qx.Inst_Id, Qx.Session_Id, Qx.User_Id, Qx.Sql_Id, Qx.Sql_Exec_Id
                 ORDER BY Units DESC) Q1
         WHERE Rownum <= 30) Q2
 INNER JOIN Dba_Users Du
    ON Q2.User_Id = Du.User_Id
 ORDER BY Q2.Inst_Id, Q2.Units DESC, Q2.Start_Time DESC, Q2.Sid, Q2.Sql_Id, Q2.Sql_Exec_Id;



------- ------ ------------- ---------- ------------- -----  --------------------------------------------------------------------------------
      1    839 2srp700w8cahb 16:18:46   USERX0000110    127  ON CPU(75), db file sequential read(44), db file scattered read(4), gc current grant 2-way(4)
      1   2686                          USERX0000110     48  ON CPU(26), log file sync(16), SQL*Net vector data from client(4), enq: FB - contention(2)
      1    759                          SYS              39  ON CPU(35), gcs log flush sync(3), buffer busy waits(1)
      1    381                          SYS              38  log file parallel write(36), ON CPU(2)
      1   2271                          SYS              38  ON CPU(35), db file parallel write(3)
      1    839 cz1nr2ns6ukrs 16:13:31   USERX0000110     38  ON CPU(26), gc current block 2-way(8), db file sequential read(4)
      1    380                          SYS              36  ON CPU(30), gcs log flush sync(6)
      1   2713 068k748nv9bcd 16:18:40   USERX0000110     32  db file scattered read(13), db file sequential read(9), db file parallel read(6), ON CPU(4)
      1   1540 3ungrdz7xhmr6 16:22:49   USERX0000110     27  db file sequential read(18), db file parallel read(6), ON CPU(2), db file scattered read(1)
      1   2713 axxar2md3papc 16:17:54   USERX0000110     21  db file parallel read(8), db file scattered read(4), gc cr multi block request(4), ON CPU(3), db file sequential read(1), gc current block 2-way(1)
      1   2713 02r3k87r3rvt1 16:19:15   USERX0000110     20  ON CPU(19), db file scattered read(1)
      1   2713 80rfxjnb0yrhk 16:19:39   USERX0000110     13  db file sequential read(12), ON CPU(1)
      1    468 3ungrdz7xhmr6 16:22:29   USERX0000110     11  db file sequential read(10), ON CPU(1)

      2   2333 45r3aaavfuppg 16:20:42   USERX0000110    746  ON CPU(647), db file parallel read(39), gc cr multi block request(29), db file scattered read(21), direct path write temp(4), db file sequential read(3), direct path read temp(2), gc cr grant 2-way(1)
      2   2333 68gmznp793ww8 16:16:57   USERX0000110    149  ON CPU(81), db file sequential read(29), gc cr multi block request(25), db file parallel read(8), db file scattered read(5), gc cr grant 2-way(1)
      2    796                          USERX0000110    138  ON CPU(84), log file sync(49), SQL*Net vector data from client(5)
      2    381                          SYS              82  log file parallel write(66), ON CPU(9), LGWR wait for redo copy(7)
      2    451 4b7msmfyy2azz 16:21:48   USERX0000120     22  db file sequential read(22)
      2    759                          SYS              14  ON CPU(14)
      2   1525 am4159anfcr73 16:28:40   USERX0000110     14  db file sequential read(14)
      2    451 4b7msmfyy2azz 16:23:59   USERX0000110     14  db file sequential read(14)
      2    451 4b7msmfyy2azz 16:21:27   USERX0000110     14  db file sequential read(14)
      2    380                          SYS              13  ON CPU(13)
      2    814 154kp34at43ug 16:30:17   USERX0000100     13  db file parallel read(6), db file scattered read(3), db file sequential read(3), ON CPU(1)
      2    843 6yn2u5t0hdbxf 16:25:18   USERX0000110     12  enq: TX - row lock contention(12)
      2    814 5du5nbsh64u59 16:30:34   USERX0000100     11  ON CPU(5), db file sequential read(3), gc cr multi block request(3)
      2   2271                          SYS              10  ON CPU(10)
      2    814 2n98kzqy16drj 16:30:52   USERX0000100     10  db file scattered read(5), ON CPU(3), db file parallel read(2)
      2   1220 6yn2u5t0hdbxf 16:23:25   USERX0000110      9  enq: TX - row lock contention(9)
      2    451 4b7msmfyy2azz 16:21:10   USERX0000110      9  db file sequential read(8), gc cr grant 2-way(1)

30 rows selected


I hope I could start your interest in diving deeper into the Oracle Active Session History.




Reader Comments

There are no comments for this journal entry. To create a new comment, use the form below.

PostPost a New Comment

Enter your information below to add a new comment.

My response is on my own website »
Author Email (optional):
Author URL (optional):
Some HTML allowed: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <code> <em> <i> <strike> <strong>