Finding the slowest SQL execution of the same query

21 thoughts on “Finding the slowest SQL execution of the same query”

• Hi Kyle,

  Below is the output from one of my database:

  SQL_ID CT MX MN AV MAX_RUN_TIME LONGEST_SQ 1 2 3 4 5
  ————- —— ———- —- ——– ———————————– ———- —— —— —– —- —
  2ahhqkpm9ywfc 3 6010 430 2438.0 13-03-15 02:50:53 13-09-11 18:07:18 16777216 2 0 0 0 1

  Query did not ran for 6 months. SQL_EXEC_ID is not always unique (http://blog.tanelpoder.com/2011/10/24/what-the-heck-is-the-sql-execution-id-sql_exec_id/ Please see Coskan and Tanel comments). In my case, I have only 3 distinct SQL_EXEC_ID for 180 executions.

  Thanks,
  Vishal

• Thanks for the link to Tanel’s stuff. From what Tanel is saying the SQL_EXEC_ID will repeat across database bounces and across wraps of the counter. Nothing suprising there.
  It looked like Coskan was saying there were bugs but I didn’t see any confirmation of that – maybe I skimmed the article too fast.
  Does make me wonder if it’s worth adding in SQL_START_ID to the above query in your case and seeing if it helps.
  like this

  col 1 for 99999
  col 2 for 99999
  col 3 for 9999
  col 4 for 999
  col 5 for 99
  col av for 99999
  col ct for 99999
  col mn for 999
  col av for 99999.9
  col MAX_RUN_TIME for a32
  col longest_sql_exec_id for A20

  WITH pivot_data AS (
  SELECT
  sql_id,
  ct,
  mxdelta mx,
  mndelta mn,
  round(avdelta) av,
  WIDTH_BUCKET(delta_in_seconds,mndelta,mxdelta+.1,5) AS bucket ,
  SUBSTR(times,12) max_run_time,
  SUBSTR(longest_sql_exec_id, 12) longest_sql_exec_id
  FROM (
  SELECT
  sql_id,
  delta_in_seconds,
  COUNT(*) OVER (PARTITION BY sql_id) ct,
  MAX(delta_in_seconds) OVER (PARTITION BY sql_id) mxdelta,
  MIN(delta_in_seconds) OVER (PARTITION BY sql_id) mndelta,
  AVG(delta_in_seconds) OVER (PARTITION BY sql_id) avdelta,
  MAX(times) OVER (PARTITION BY sql_id) times,
  MAX(longest_sql_exec_id) OVER (PARTITION BY sql_id) longest_sql_exec_id
  FROM (
  SELECT
  sql_id,
  sql_exec_id,
  MAX(delta_in_seconds) delta_in_seconds ,
  LPAD(ROUND(MAX(delta_in_seconds),0),10) || ‘ ‘ ||
  TO_CHAR(MIN(start_time),’YY-MM-DD HH24:MI:SS’) || ‘ ‘ ||
  TO_CHAR(MAX(end_time),’YY-MM-DD HH24:MI:SS’) times,
  LPAD(ROUND(MAX(delta_in_seconds),0),10) || ‘ ‘ ||
  TO_CHAR(MAX(sql_exec_id)) longest_sql_exec_id
  FROM ( SELECT
  sql_id,
  to_char(sql_exec_id)||’_’||to_char(sql_exec_start,’J’) sql_exec_id,
  CAST(sample_time AS DATE) end_time,
  CAST(sql_exec_start AS DATE) start_time,
  ((CAST(sample_time AS DATE)) –
  (CAST(sql_exec_start AS DATE))) * (3600*24) delta_in_seconds
  FROM
  dba_hist_active_sess_history
  WHERE sql_exec_id IS NOT NULL
  )
  GROUP BY sql_id,sql_exec_id
  )
  )
  where ct > &min_repeat_executions_filter
  and mxdelta > &min_elapsed_time
  )
  SELECT * FROM pivot_data
  PIVOT ( COUNT(*) FOR bucket IN (1,2,3,4,5))
  ORDER BY mx DESC,av DESC
  ;

• That was it.

  SQL_ID CT MX MN AV MAX_RUN_TIME LONGEST_SQL_EXEC_ID 1 2 3 4 5
  ————- —— ———- —- ——– ——————————– ——————– —— —— —– —- —
  2ahhqkpm9ywfc 173 6010 29 532.0 13-08-20 01:02:41 13-08-20 02:42 16777216_2456525 161 9 0 2 1
  :51

  Thanks for quick response.

• Hi kyle , How do you interpret histogram buckets ? in your example the sqlid 8rua4c9agcqkb has 978 executions and the max elapsed time for that query is 820 seconds and in histogram
  We have 5 buckets and the query ran 830 times <= second and 2 times out of 978 runs ran in 5a seconds. ??

  SQL_ID CT MX MN AV MAX_RUN_TIME 1 2 3 4 5
  ————- —— ———- —- ——– ———————————– —— —— —– —- —
  8rua4c9agcqkb 978 820 0 72.7 11-03-01 23:13:50 11-03-01 23:13:56 830 116 21 9 2

  Thanks
  Raj

• The histogram buckets 1-5 simply divide the max time into 5 intervals.
  Your max time was 820, so your intervals each of a width of 820/5 = 164
  bucket 1 : 0 -164 with 830 executions
  bucket 2: 165- 328 with 115 executions
  bucket 3: 329 – 492 with 21 executions
  bucket 4: 493- 656 with 9 executions
  bucket 5: 657 – 820 with 2 executions (one of which is the 820 second one)

• Thanks kyle for quick response

• Hi Kyle :

  While this looks good to get the count, max, min time for a query ID.

  Is there any way of knowing start time and end time of a particular sql_id :

  For example taking your query output / results :

  SQL_ID COUNT(*) MN AV MX MAX_RUN_TIME
  ————- ———- ——– ——– ——– ———————————–
  155vjqzjqp58f 27 0 115 786 11-04-11 07:39:47 11-04-11 07:41:20

  So :
  1) Can i know the start and end times of this SQL_ID which shows as run 27 times.
  2) Obviously along with this, other information like I/O , rows-fetched, cpu time, and also the cost.

• @Sai: in your example the query has been run 27 times. You could output the start and end for all 27 but that would be a lot of output. The last query above gives the start and end for the longest which is the one I generally find of the most interest.
  You could of course add the I/O, CPU and such for each execution. I haven’t looked into it, but I imagine you could also add the rows fetched and the cost as well. Seems do-able.

• Hi Kyle,
  I am getting count(no.of executions) mismatches.
  SQL> select sum(count(*)) from DBA_HIST_ACTIVE_SESS_HISTORY where sql_id=’0aj463w5jz8bw’ group by sql_id,sql_exec_id;

  SUM(COUNT(*))
  ————-
  79402

  below shows only 4868. I used where ct > &min_repeat_executions_filter (1)
  and mxdelta > &min_elapsed_time (0)

  SQL_ID CT MX MN AV MAX_RUN_TIME LONGEST_SQ 1 2 3 4 5
  ————- —— ——– —- ——– ——————————————————————————————————————————————————————————————————————————————————————– ———- —— —— —– —- —
  0aj463w5jz8bw 4868 2865 0 156.0 14-12-09 09:26:40 14-12-09 10:14:25 16795025 4475 326 62 0 5

• @anthony
  If you want to send me an export of your DBA_HIST_ACTIVE_SESS_HISTORY I’ll take a look at it. Your second query is slightly off, though not sure if that could explain the difference.

• SQL> USED v$active_session_history in your query,it shows execution count as 7 which is right.

  SQL_ID COUNT(*) MN AV MX MAX_RUN_TIME
  ————- ———- ——– ——– ——– ——————————————-
  1gqww8makf6w5 7 2 4 6 14-12-12 13:06:39 14-12-12 13:06:45

  — again with DBA_HIST_ACTIVE_SESS_HISTORY in your query, the execution count shows 2

  SQL_ID COUNT(*) MN AV MX MAX_RUN_TIME
  ————- ———- ——– ——– ——– ——————————————-
  1gqww8makf6w5 2 5 6 6 14-12-12 13:05:44 14-12-12 13:05:50

  SQL> @sqlstat 1gqww8makf6w5 from DBA_HIST_SQLSTAT shows 7 executions (4 and 3 in two snapshot intervals)

  INTERVAL SQL_ID PLAN_HASH_VALUE EXECUTIONS ELAPSED_SEC ELAPSED_PER_EXEC_SEC
  ——————– ————- ————— ———- ———– ——————–
  12-12-2014 12:14 1gqww8makf6w5 3724264953 4 9 2
  12-12-2014 13:00 1gqww8makf6w5 3724264953 3 17 6

  Correct me, if i am wrong. Your query’s execution count is not matching with the actual number of executions.

• @khailey
  Could you please delete the contents dbname & hostname in the SQL prompt from comment# 11 as it has sensitive info? sorry for the inconvenience.

• @khailey
  SQL> select sum(count(*)) from DBA_HIST_ACTIVE_SESS_HISTORY where sql_id=’0aj463w5jz8bw’ and sql_exec_id is not null group by sql_id,sql_exec_start,sql_exec_id;

  SUM(COUNT(*))
  ————-
  80144

  SQL_ID CT MX MN AV MAX_RUN_TIME LONGEST_SQ 1 2 3 4 5
  ————- —— ———- —- ——– ——————————————————————————————————————————————————————————————————————————————————————– ———- —— —— —– —- —
  0aj463w5jz8bw 4906 2865 0 156.0 14-12-09 09:26:40 14-12-09 10:14:25 16795025 4511 328 62 0 5

  Still there is a difference.

• Hi Kyle,
  I guess the algorithm behind flushing 1/10 of the sample to historical tables could be the root cause as why there are differences in the number of executions.A simple test reveals that not all distinct SQL_EXEC_IDs are flushed out to AWR tables.

  SQL> select distinct sql_exec_id from V$ACTIVE_SESSION_HISTORY where sql_id=’1gqww8makf6w5′ order by sql_exec_id; –> Actual number of executions

  SQL_EXEC_ID
  ———–
  16777216
  16777217
  16777218
  16777219
  16777220
  16777221
  16777222
  16777223
  16777224

  SQL> select distinct sql_exec_id from DBA_HIST_ACTIVE_SESS_HISTORY where sql_id=’1gqww8makf6w5′ order by sql_exec_id;

  SQL_EXEC_ID
  ———–
  16777220
  16777221
  16777223
  16777224

  I have also observed that the flushing algorithm is not giving weightage to number of samples specific to a sql execution.In my test,as you can see below both sql_exec_ids 16777222 and 16777224 have 5 samples each in ASH.But 16777222 is missing from AWR.

  SQL> select sql_exec_id,count(*) from V$ACTIVE_SESSION_HISTORY where sql_id=’1gqww8makf6w5′ group by sql_exec_id;

  SQL_EXEC_ID COUNT(*)
  ———– ———-
  16777222 5 <<<
  16777221 6
  16777223 6
  16777220 6
  16777217 3
  16777224 5 <<<
  16777219 2
  16777218 3
  16777216 3

  But your thought process deserves more credit.Keep up the good work that you're doing.

  Thanks
  Antony

• yes, v$active_session_history and dba_hist_active_sess_history are different
  but in your comparison you are using dba_hist_active_sess_history for both so the results should be the same
  again you can send me an export of dba_hist_active_sess_history and I will look at it.
  Comparing on my system they are eactly the same

• Hi Kyle,
  I sent you (GMAIL) my dba_hist_active_session history for one SQL_ID.The file will have insert statments to a table called DASH.
  Thanks again for checking this one.

• @Antony,

  I think what you want is

  select count(distinct sql_exec_id||sql_exec_start) from DASH where sql_id=’0aj463w5jz8bw’;

  to get the number of distinct executions for a particular sql_id;

  COUNT(DISTINCTSQL_EXEC_ID||SQL_EXEC_START)
  ——————————————
  5105

  compares to

  SQL_ID CT MX MN AV MAX_RUN_TIME LONGEST_SQL_EXEC_ID 1 2 3 4 5
  ————- —— ———- —- ——– ———————————– ——————– —— —— —– —- —
  0aj463w5jz8bw 5105 85420 856 31997.0 14-10-24 00.00.00 14-10-24 23.43.40 16780545_2456955 1691 1312 1094 575 ###

• Thanks Kyle!
  Most of the variations in sql execution run time caused by change in execution plan or due to bind variable peeking.looking for the possibilities of drilling down further with a bind values associated with long run.

• @anthony – yes adding bind variable capturing would be nice but I don’t think there is a efficient way to capture all the bind variables. AFAIK, other than tracing, one can only capture a some of the bind variables.

• I am amazed with your thought process of adding buckets in this sql. Another observation which I came across today while using the SQL is that there are SQLs which might not be completed for ever or killed after n minutes of executions(we have one in our shop for SQL queries from sql developer) but still contributed towards max_run_time.I had to compare the sql_id with executions_delta of DBA_HIST_SQLSTAT by filtering executions_delta>0.

• I’ve included the version that we use below. We just tracked down a problem in our java code that was due to dba_hist_active_sess_history.sql_exec_start being NULL. This seems to be very rare. (We execute this query as part of our instrumentation at the end of every performance test and have been doing so since shortly after I saw your blog post.) The NULL screwed up our analysis of the encoded string for max_run_time. We added a WHERE clause to filter out rows that have a NULL value.

  Jerry

  WITH pivot_data AS
  (SELECT sql_id , instance_number , ct , mxdelta mx , mndelta mn , avdelta av ,
  width_bucket ( delta_in_seconds,mndelta-.1,mxdelta+.1,5 ) AS bucket ,
  SUBSTR( times,12 ) max_run_time ,
  SUBSTR( longest_sql_exec_id, 12 ) longest_sql_exec_id ,
  SUBSTR( longest_sql_exec_id_action, 12 ) longest_sql_exec_id_action,
  SUBSTR( longest_sql_exec_id_client_id, 12 ) longest_sql_exec_id_client_id
  FROM
  (SELECT sql_id , instance_number , delta_in_seconds ,
  COUNT (*) OVER ( PARTITION BY sql_id, instance_number ) ct ,
  MAX ( delta_in_seconds ) OVER ( PARTITION BY sql_id, instance_number ) mxdelta ,
  MIN ( delta_in_seconds ) OVER ( PARTITION BY sql_id, instance_number ) mndelta ,
  AVG ( delta_in_seconds ) OVER ( PARTITION BY sql_id, instance_number ) avdelta ,
  MAX ( times ) OVER ( PARTITION BY sql_id, instance_number ) times ,
  MAX ( longest_sql_exec_id ) OVER ( PARTITION BY sql_id, instance_number ) longest_sql_exec_id ,
  MAX ( longest_sql_exec_id_action ) OVER ( PARTITION BY sql_id, instance_number ) longest_sql_exec_id_action,
  MAX ( longest_sql_exec_id_client_id ) OVER ( PARTITION BY sql_id, instance_number ) longest_sql_exec_id_client_id
  FROM
  (SELECT sql_id , sql_exec_id , instance_number , MAX (delta_in_seconds) delta_in_seconds ,
  LPAD( ROUND ( MAX ( delta_in_seconds ) ,0 ) ,10)
  || ‘ ‘
  || TO_CHAR ( MIN ( start_time ) , ‘YYYY-MM-DD HH24:MI:SS’ )
  || ‘$’
  || TO_CHAR ( MAX ( end_time ) , ‘YYYY-MM-DD HH24:MI:SS’ ) times,
  LPAD( ROUND ( MAX ( delta_in_seconds ) ,0 ) ,10)
  || ‘ ‘
  || TO_CHAR ( MAX ( sql_exec_id ) ) longest_sql_exec_id,
  LPAD( ROUND ( MAX ( delta_in_seconds ) ,0 ) ,10)
  || ‘ ‘
  || TO_CHAR ( MAX ( action ) ) longest_sql_exec_id_action,
  LPAD( ROUND ( MAX ( delta_in_seconds ) ,0 ) ,10)
  || ‘ ‘
  || TO_CHAR ( MAX ( client_id ) ) longest_sql_exec_id_client_id
  FROM
  (SELECT sql_id , sql_exec_id , instance_number , action , client_id ,
  CAST ( sample_time AS DATE ) end_time , CAST ( sql_exec_start AS DATE ) start_time,
  ( ( CAST ( sample_time AS DATE ) ) – ( CAST ( sql_exec_start AS DATE ) ) ) * ( 3600*24 ) delta_in_seconds
  FROM dba_hist_active_sess_history
  WHERE sql_exec_id IS NOT NULL
  AND module = ‘BillingCenter_MKTG’
  AND snap_id BETWEEN 375 AND 382
  )
  GROUP BY sql_id , sql_exec_id, instance_number
  )
  )
  )
  SELECT sql_id , instance_number , ct , mx , mn , av , max_run_time ,
  longest_sql_exec_id , longest_sql_exec_id_action , longest_sql_exec_id_client_id, “1” , “2” , “3” , “4” , “5”
  FROM pivot_data PIVOT ( COUNT (*) FOR bucket IN ( 1,2,3,4,5 ) )
  ORDER BY mx DESC , av DESC;

Comments are closed.