ASH script to show query run times

I ran into a situation last week where a developer complained that a query sometimes ran for 3 or more seconds but normally runs much less than 1 second. I had just been to a local AZORA user group meeting where Tim Gorman talked about using ASH to diagnose issues so Tim’s talk motivated me to find some clever way to use ASH. I had these three pairs of start and stop dates and times to work with. Each was about 3 to 4 seconds apart. I started looking at DBA_HIST_ACTIVE_SESS_HISTORY for the time period or even a large 11 second time period that bracketed the interval but I did not get any rows back for the first two intervals and only one row for the third. I knew that the V$ version of ASH sampled every 1 second so it might catch these 3 second queries but the queries in question had run the day before. But, something Tim said in the user group meeting made me think about using the V$ view. He said that on inactive development databases the in-memory V$ ASH data could hang around for a few days. Sure enough I was able to find some information in one of the given time periods. But, then I had to find the one slow execution of the query because there were multiple executions at the same time. I found that grouping by SQL_EXEC_ID would let me see each execution of the query by itself. So, I developed this query to show how long each execution ran:

select 
SQL_EXEC_ID,
to_char(SQL_EXEC_START,'YYYY-MM-DD HH24:MI:SS') sql_start,
to_char(min(sample_time),'YYYY-MM-DD HH24:MI:SS') first_sample,
to_char(max(sample_time),'YYYY-MM-DD HH24:MI:SS') last_sample,
max(sample_time)-min(sample_time) elapsed_seconds
from V$ACTIVE_SESSION_HISTORY a
where 
sample_time 
between 
to_date('20-OCT-2016 17:00:00','DD-MON-YYYY HH24:MI:SS')
and 
to_date('20-OCT-2016 17:30:00','DD-MON-YYYY HH24:MI:SS') and
sql_id='0gt3cjptk68vw'
group by SQL_EXEC_ID,SQL_EXEC_START
order by SQL_EXEC_START,SQL_EXEC_ID;

Here are a few rows from the output from around the time of the first interval that I was looking at:

SQL_EXEC_ID SQL_START           FIRST_SAMPLE        LAST_SAMPLE         ELAPSED_SECONDS
----------- ------------------- ------------------- ------------------- -----------------------
   16785284 2016-10-20 17:05:24 2016-10-20 17:05:25 2016-10-20 17:05:25 +000000000 00:00:00.000
   16785285 2016-10-20 17:05:25 2016-10-20 17:05:25 2016-10-20 17:05:25 +000000000 00:00:00.000
   16785380 2016-10-20 17:05:31 2016-10-20 17:05:31 2016-10-20 17:05:34 +000000000 00:00:03.000
   16785692 2016-10-20 17:05:51 2016-10-20 17:05:52 2016-10-20 17:05:53 +000000000 00:00:01.000
   16785772 2016-10-20 17:05:54 2016-10-20 17:05:55 2016-10-20 17:05:55 +000000000 00:00:00.000
   16785852 2016-10-20 17:05:59 2016-10-20 17:06:01 2016-10-20 17:06:01 +000000000 00:00:00.000
   16785940 2016-10-20 17:06:07 2016-10-20 17:06:08 2016-10-20 17:06:08 +000000000 00:00:00.000

The third row down lined up well with the interval in question. So, I was able to use ASH to show that the query ran for 3 seconds within the database. Also, each line was a wait on db file sequential read. This lead me to look at the execution plan and to check the index and partitioning to look for ways to improve the query’s performance.

Bobby

 

About Bobby

I live in Chandler, Arizona with my wife and three daughters. I work for US Foods, the second largest food distribution company in the United States. I have worked in the Information Technology field since 1989. I have a passion for Oracle database performance tuning because I enjoy challenging technical problems that require an understanding of computer science. I enjoy communicating with people about my work.
This entry was posted in Uncategorized. Bookmark the permalink.

6 Responses to ASH script to show query run times

  1. Kevin says:

    Which Oracle DB version are you using here? Will this SQL work with 10g?

    • Bobby says:

      The database that I was working on was on 11.2.0.4. I tried the same query on a 10.2.0.4 database and got this error:

      ORA-00904: “SQL_EXEC_START”: invalid identifier

      It looks like a lot of new columns were added to the ASH views with version 11. I think that Tim Gorman mentioned this in his talk as well.

      Bobby

  2. Kyle Hailey says:

    good stuff. When through a similar path a few years ago. Here are some more scripts:
    http://datavirtualizer.com/finding-the-slowest-sql-execution-of-the-same-query/
    and like you I put them on github – a great place to centralize and share scripts
    https://github.com/khailey/ashmasters

  3. Kyle Hailey says:

    PS some of this is presented in the ASHmasters presentation http://www.slideshare.net/khailey/ash-masters-advanced-ash-analytics-on-oracle. Top SQL stuff starts on slide 74

Leave a Reply

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

This site uses Akismet to reduce spam. Learn how your comment data is processed.