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


Uncategorized

  1. Trackbacks

  2. December 28th, 2012: dboptimizer.com | xfang
  1. Comments

  2. Kyle Hailey
    May 6th, 2011 at 14:24 | #1

    Modified the above query after talking with Karl Arao who pointed out that there was no need to self join dba_active_sess_history, so above it’s all done in one query.

  3. Kyle Hailey
    May 6th, 2011 at 23:56 | #2

    If you use SASH you can do similar queries using fixed_table_sequence:
    This shows the top twolongest running queries every 15 minute period. The higher the count the longer
    they have been running (you can’t do this with 10g ASH)

       START_TIME     COUNT(*)     SQL_ID FIXED_TABLE_SEQUENCE       TOPN
       ------------ ---------- ---------- -------------------- ----------
       JUN-01 02:00         29  795857215                34254          1
       JUN-01 02:00         29  795857215                34547          1
       JUN-01 02:00         29  986013188                34305          1
       JUN-01 02:15        105  452165714                35961          1
       JUN-01 02:15        102  866152581                35999          2
       JUN-01 02:30        119 2586830956                39017          1
       JUN-01 02:30        109  452165714                39130          2
    
    break on  start_time
    clear breaks
    column f_secs new_value v_secs
    column f_mins new_value v_mins
    select 900 f_secs from dual;
    select &v_secs/60 f_mins from dual;
    
    select * from (
       select
            to_char(trunc(sample_time,'HH')+
                 (trunc((sample_time-trunc(sample_time,'HH'))*24/(&v_mins/60))+1)/(60/&v_mins)/24 ,'MON-DD HH:MI') start_time,
            count(*),
            sql_id,
            fixed_table_sequence,
            rank()
              over (
                partition by
                        trunc(sample_time,'HH')+
                 (trunc((sample_time-trunc(sample_time,'HH'))*24/(&v_mins/60))+1)/(60/&v_mins)/24
                order by count(*) desc ) topn
       from sash
       where
              sql_id > 0
         and  sql_id is not null
         and  sample_time > sysdate - (30)/(24*60)
       group by
                sql_id,
                fixed_table_sequence,
                trunc(sample_time,'HH')+
                (trunc((sample_time-trunc(sample_time,'HH'))*24/(&v_mins/60))+1)/(60/&v_mins)/24
    )
    where  topn < 3
    /
    clear breaks
    
    
  4. May 11th, 2011 at 11:54 | #3

    Hi Kyle,

    Script is very useful and sql_exec_id is very wise to use.

    One thing to bear in mind, I don’t know if it is a bug on our 11.2.0.1 DB but I can see a sql which runs 2 seconds has got sql_exec_start_date back in 15 days ago which can cause misleading conclusions with the sql you shared.

  5. Kyle Hailey
    May 13th, 2011 at 04:33 | #4

    @coskan gundogar
    Hi Coskan,
    Do you have any example output? Or better yet an export of the AWR that I could import and run queries on?
    THanks
    Kyle

  6. July 20th, 2011 at 18:47 | #5

    @Kyle Hailey
    SOmething like this should work with SASH for queries over 5 minutes:

    select * from (
       select
            count(*),
            sql_id,
            fixed_table_sequence
       from sash
       where
              sql_id > 0
         and  sql_id is not null
       group by
                sql_id,
                fixed_table_sequence,
       having count(*) > 300 
    /
    
  7. lmwang
    June 3rd, 2013 at 01:55 | #6

    Hi Kyle,
    Do MX AV MIN mean in seconds?
    THanks
    lmwang

  8. June 3rd, 2013 at 03:57 | #7

    MX AV and MIN are the maximum, average and minimum execution times for the SQL statements in seconds, but seconds based on ASH sampling, so it’s not exact but statistically sufficient for queries that take more than a second.


× five = 45