Tracking historic SQL execution time with ASH

Today, I spent a fair amount of time anaylizing a few statements. One of them was used to retrieve data for display on a webpage and it took almost 4 seconds to execute this statement. This is still acceptable but could be better. Tuning this will not be an easy task and is out of the scope of this blog post. But I had one question that was really nagging me all day: How long did this statement take in the past? I could use this information to assess if this is a new problem or not and also estimate/project if this will get even worse in the future.

After a while I remembered that Oracle already stores most of these statistics in the active session history so retrieving and analyzing becomes a very simple task. I decided to compare the weekly average execution time with this statement:

SELECT
  trunc(begin_interval_time, 'WW'),
  ROUND(sum(elapsed_time_delta)/sum(executions_delta)/1000)
FROM dba_hist_sqlstat a
JOIN dba_hist_snapshot b
ON a.snap_id = b.snap_id
WHERE sql_id        = 'avaavbkx3017y'
AND executions_delta>0 
GROUP BY trunc(begin_interval_time, 'WW')
ORDER by trunc(begin_interval_time, 'WW') DESC

The result was that this statement has always taken about 4 seconds for as long as I have ASH data. Neat.

In the process of all this I also found out that by saving a statement as a report you can even generate a nice chart directly from SQLDeveloper. The only catch is that you need to specify three columns when you do this. The error message “Invalid column index: getValidColumnIndex” did not help a whole lot in diagnosing this but eventually I found this blog post by Sue Harper. Too bad she left Oracle a few months ago.

I know that I am not a pioneer in this, so if you know of good resources, ASH scripts and such, please leave a comment.

3 thoughts on “Tracking historic SQL execution time with ASH

  1. Bjoern,
    you can get even more informations out of you graph:
    There seems to be a baseline from March 2011? It is much worse (> +50%) than the others. If you know the situation in which it was created, you might get a better understanding for a worst case you like to know.
    Another information there is: Every 2nd week per month is approx 10% to 20% slower than the other weeks. In general, 10-20% is nothing an enduser will complain about, but again it might be worth to understand it, especially in case you want to tune it. Otherwise the different circumstances during these days can blast all your efforts for ordinary days.
    At the end, a little hair-splitting: afaik ASH reflects only v$active_session_history whereas AWR sums up all DBA_HIST_% views. :wink:
    Martin

  2. Thanks Martin,

    I saw these aswell and I can explain. Earlier this year, we added another disk shelf for more spindles and better IO performance. 98% of this SQL is waiting on “db file sequential read” so the increase in IO performance was immediately visible. About the increase every couple of weeks: The statement works on a partitioned table and is scanning 3 or 4 partitions depending on the time of the query. I knew this is taking place but I was also surprised (and excited) to see this in the report.
    I also have a very good understanding about the query, it is an indexed lookup on a huge table. Since we cannot hold the table in the buffer cache, we have to read a lot of blocks from all over the place.
    I am thinking about converting this to a hash cluster so that all the rows that get queried together also get stored together to reduce the number of random IOs.

    I think you are right about AWR/ASH. dba_hist_active_sess_stat is also part of ASH. And I guess AWR snapshots use this data and store it in dba_hist_sqlstat.

Leave a Reply

Your email address will not be published. Required fields are marked *