SQL execution times from ASH

1. http://dboptimizer.com/2011/05/04/sql-execution-times-from-ash/

2. http://dboptimizer.com/2011/05/06/sql-timings-for-ash-ii/

3. http://dboptimizer.com/2011/05/06/sql-ash-timings-iii/

Update: Check out Tanel Poder’s blog entry on SQL_EXEC_ID for more details, especially for the RAC world: Tanel Poder’s blog on SQL_EXEC_ID

Something I’ve been looking forward to exploiting for a while is the SQL_EXEC_ID field in ASH. Thanks to Karl Arao for pushing me to look into this. Karl sent me an example query he had written using SQL_EXEC_ID and then we started discussing how to harness SQL_EXEC_ID. (see Karl’s blog here http://karlarao.wordpress.com/ and some good examples of SQL_EXEC_ID here http://karlarao.tiddlyspot.com/#Elapsed-AvgMinMax) One of the several cool things about ASH in Oracle 11g is there is now a SQL_EXEC_ID column. What good is the SQL_EXEC_ID column? Well without it , like in Oracle 10g there was no way to look at ASH data and distinguish between a SQL statement that had been re-executed multiple times in a row and showed up in consecutive ASH samples and a SQL statement that was running for a long time and showing up in consecutive ASH samples. Now in 11g with SQL_EXEC_ID we can now make the distinction. (the distinction can actually be done  since Oracle version 7 with SASH – simulated ASH). Now with SQL_EXEC_ID not only can we distinguish long running queries from re-executed queries we can start looking at  average execution times and maximum execution times and start seeing variation. These timings though are only accurate for longer running queries as fast running queries running faster than 1 second will only appear once per execute in ASH thus no deltas can be calculated.

Here is an example SQL execution timing data mining query (ashsqlt.sql):

col mx for 999999
col mn for 999999
col av for 999999.9

select
       sql_id,
       count(*),
       max(tm) mx,
       avg(tm) av,
       min(tm) min
from (
   select
        sql_id,
        sql_exec_id,
        max(tm) tm
   from ( select
              sql_id,
              sql_exec_id,
              ((cast(sample_time  as date)) -
              (cast(sql_exec_start as date))) * (3600*24) tm
           from
              dba_hist_active_sess_history
           where sql_exec_id is not null
	)
   group by sql_id,sql_exec_id
   )
group by sql_id
having count(*) > 10
order by mx,av
/

and the output looks like

SQL_ID          COUNT(*)      MX        AV        MIN
------------- ---------- ------- --------- ----------
2h83mk46003q4         18       1        .2          0
77m98gu3uzb59         15       1        .2          0
6dnvpqs0zdxhv         30       1        .3          0
40r79s5rxabwr         18       1        .3          0
26ugyh75gmnt4         35       1        .3          0
1sjkhrtg3qa48         14       1        .3          0
4h6kn70hsgz9u         20       1        .3          0
b6s2h63d07t91         13       1        .3          0
a18wua1f703xh         29       1        .3          0
6az55y9y8u86c         12       1        .3          0
7ujfmgb1j83a3         21       1        .3          0

above is the beginning and times below is the end of output

SQL_ID          COUNT(*)      MX        AV        MIN
------------- ---------- ------- --------- ----------
0fvrpk7476b7y         26    3068     133.1          0
1pjp66rxcj6tg         15    3106     767.7         57
8r5wuxk1dprhr         39    3510     841.0         24
0w5uu5kngyyty         21    3652     442.3          0
0hbv80w9ypy0n        161    4089    1183.9          0
71fwb4n6a92fv         49    4481     676.9         30
0bujgc94rg3fj        604    4929      24.7          0
64dqhdkkw63fd       1083    7147       7.2          0
990m08w8xav7s        591    7681      51.8          0
2n5369dsuvn5a         16   10472    5726.8        303
2spgk3k0f7quz        251   29607     546.1          0
36pd759xym9tc         12   37934   23861.9       1391
497wh6n7hu14f         49   69438    5498.2          0