SQL ASH timings III
May 6th, 2011
in the last two SQL ASH timing posts we looked at
all three links:
- http://dboptimizer.com/2011/05/04/sql-execution-times-from-ash/
- http://dboptimizer.com/2011/05/06/sql-timings-for-ash-ii/
- http://dboptimizer.com/2011/05/06/sql-ash-timings-iii/
Another question that comes to mind, is “when did the slowest running query happen?” (and ultimately what is the timeline of executions and elapses times)
col av for 9999999
col mx for 9999999
col mn for 9999999
select
sql_id,
count(*),
round(min(delta),0) mn,
round(avg(delta),0) av,
round(max(delta),0) mx,
substr(max(times),12) max_run_time
from (
select
sql_id,
sql_exec_id,
max(delta) delta ,
-- lpad sets a fixed width on delta so it can be
-- stripped off above with substr
-- delta in "times" is just for sorting not displaying
lpad(round(max(delta),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
from ( select
sql_id,
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
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
/
|
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 7nf5917x3tq5x 113 0 129 791 11-04-11 01:03:19 11-03-02 04:16:09 asg774pz0kqga 11 11 225 799 11-04-14 12:20:10 11-03-02 12:18:58 1kf1jsykb1nk6 529 0 107 800 11-04-09 18:41:28 11-03-01 23:13:56 8rua4c9agcqkb 978 0 73 820 11-03-01 23:13:50 11-03-01 23:13:56 fdagtr1sdk8tn 313 0 242 841 11-04-08 21:30:31 11-04-08 21:30:38 7b5w34atn8q1h 124 0 25 898 11-03-07 20:53:17 11-03-07 20:53:23 9w7mbuv734tfy 11 30 509 954 11-04-14 09:00:55 11-03-02 04:27:33 88qxmg220db9s 23 4 357 1040 11-04-13 22:08:20 11-04-13 02:20:09 83ngzw213v0cs 302 1 207 1122 11-04-11 16:26:32 11-03-07 16:12:11 34cgtc9xkgxny 61 978 1163 1272 11-03-02 10:06:24 11-03-02 10:06:30 g5u58zpg0tuk8 97 1 62 1359 11-04-13 02:49:33 11-04-12 02:23:39 6tkqndn1tzf23 29 7 187 1370 11-04-13 06:56:43 11-03-02 06:56:54 g4wrnvdmf23b1 11 19 458 1397 11-04-14 12:22:28 11-03-02 12:21:19 bpkg6y9wvf717 31 0 189 1427 11-04-13 21:19:51 11-03-02 21:08:00 4d6m2q3ngjcv9 320 3 485 1701 11-04-10 18:00:54 11-03-01 23:10:55 882tp5sbq1tq5 17 39 367 1795 11-04-14 14:00:30 11-03-01 23:04:33 5k7vccwjr5ahd 2653 0 33 1963 11-04-12 09:06:08 11-03-01 23:10:15 44034jty9vnrg 19 2 188 1968 11-03-03 09:17:34 11-03-03 09:17:43 g9n69a23s3wxz 40 6 280 2009 11-04-08 13:47:23 11-03-03 09:37:38 ds8cz0fb8w147 161 13 274 2531 11-04-12 16:10:21 11-03-01 23:11:55 bzyny95313u12 114 0 47 2599 11-03-03 03:06:18 11-03-03 03:06:25 0fvrpk7476b7y 26 0 133 3068 11-03-07 07:57:56 11-03-07 07:58:00 1pjp66rxcj6tg 15 57 768 3106 11-04-09 17:25:21 11-03-07 08:58:26 8r5wuxk1dprhr 39 24 841 3510 11-04-14 14:00:47 11-03-02 09:54:37 0w5uu5kngyyty 21 0 442 3652 11-04-11 08:00:21 11-04-11 09:01:13 0hbv80w9ypy0n 161 0 1184 4089 11-04-12 22:26:09 11-03-02 04:36:15 71fwb4n6a92fv 49 30 677 4481 11-04-10 17:01:17 11-03-01 23:40:45 0bujgc94rg3fj 604 0 25 4929 11-04-08 10:53:34 11-04-08 12:15:43 64dqhdkkw63fd 1083 0 7 7147 11-03-07 04:01:01 11-03-07 06:00:08 990m08w8xav7s 591 0 52 7681 11-04-13 00:39:27 11-04-13 00:39:37 2n5369dsuvn5a 16 303 5727 10472 11-04-14 11:18:11 11-04-14 14:12:43 2spgk3k0f7quz 251 0 546 29607 11-04-12 12:11:47 11-04-12 12:11:48 36pd759xym9tc 12 1391 23862 37934 11-04-13 19:25:49 11-03-01 23:00:12 497wh6n7hu14f 49 0 5498 69438 11-04-12 19:01:17 11-04-13 12:03:54 |
and we can put the histogram and the longest elapsed time dates into one query
NOTE: modified query since posting to use mindelta as low_boundery in bucket_width and changed
from
to_char(max(start_time),'YY-MM-DD HH24:MI:SS') || ' ' ||
to_char(min(end_time),'YY-MM-DD HH24:MI:SS') times
to
to_char(min(start_time),'YY-MM-DD HH24:MI:SS') || ' ' ||
to_char(max(end_time),'YY-MM-DD HH24:MI:SS') times
col 1 for 99999
col 2 for 99999
col 3 for 9999
col 4 for 999
col 5 for 99
col av for 99999.9
col ct for 99999
col mn for 999
col av for 99999.9
with pivot_data as (
select
sql_id,
ct,
mxdelta mx,
mndelta mn,
avdelta av,
-- high_boundary is set to maxdelta + 1 so that
-- nothing ends up in the overflow bucket
-- otherwise the max value ends up in the overflow bucket
width_bucket(delta,mndelta,mxdelta+1,5) as bucket ,
substr(times,12) max_run_time
from (
select
sql_id,
delta,
count(*) OVER (PARTITION BY sql_id) ct,
max(delta) OVER (PARTITION BY sql_id) mxdelta,
min(delta) OVER (PARTITION BY sql_id) mndelta,
avg(delta) OVER (PARTITION BY sql_id) avdelta,
max(times) OVER (PARTITION BY sql_id) times
from (
select
sql_id,
sql_exec_id,
max(delta) delta ,
-- lpad sets a fixed width on delta so it can be
-- stripped off above with substr
-- delta in "times" is just for sorting not displaying
lpad(round(max(delta),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
from ( select
sql_id,
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
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
)
select * from pivot_data
PIVOT ( count(*) FOR bucket IN (1,2,3,4,5))
order by mx,av;
/
|
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 fdagtr1sdk8tn 313 841 0 241.8 11-04-08 21:30:31 11-04-08 21:30:38 194 45 0 0 74 7b5w34atn8q1h 124 898 0 24.8 11-03-07 20:53:17 11-03-07 20:53:23 122 0 0 0 2 83ngzw213v0cs 302 1122 1 207.5 11-04-11 16:26:32 11-03-07 16:12:11 200 68 21 6 7 g5u58zpg0tuk8 97 1359 1 62.1 11-04-13 02:49:33 11-04-12 02:23:39 92 3 1 0 1 4d6m2q3ngjcv9 320 1701 3 484.7 11-04-10 18:00:54 11-03-01 23:10:55 92 168 50 9 1 5k7vccwjr5ahd 2653 1963 0 33.4 11-04-12 09:06:08 11-03-01 23:10:15 2623 15 8 4 3 ds8cz0fb8w147 161 2531 13 273.8 11-04-12 16:10:21 11-03-01 23:11:55 136 18 5 1 1 bzyny95313u12 114 2599 0 46.5 11-03-03 03:06:18 11-03-03 03:06:25 113 0 0 0 1 0hbv80w9ypy0n 161 4089 0 1183.9 11-04-12 22:26:09 11-03-02 04:36:15 27 116 9 6 3 71fwb4n6a92fv 49 4481 30 676.9 11-04-10 17:01:17 11-03-01 23:40:45 38 6 2 2 1 0bujgc94rg3fj 604 4929 0 24.7 11-04-08 10:53:34 11-04-08 12:15:43 601 1 1 0 1 64dqhdkkw63fd 1083 7147 0 7.2 11-03-07 04:01:01 11-03-07 06:00:08 1082 0 0 0 1 990m08w8xav7s 591 7681 0 51.8 11-04-13 00:39:27 11-04-13 00:39:37 587 0 0 2 2 2spgk3k0f7quz 251 29607 0 546.1 11-04-12 12:11:47 11-04-12 12:11:48 247 2 0 0 2 497wh6n7hu14f 49 69438 0 5498.2 11-04-12 19:01:17 11-04-13 12:03:54 44 1 0 1 3 |
NOTE: new version to include longest SQL_EXEC_ID which makes going and looking up the wait events for the longest SQL_EXEC_ID easy thanks to Jerry Brenner for this addition as well as feedback on the original
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 longest_sql_exec_id for A10
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,
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
;
|
SQL_ID CT MX MN AV MAX_RUN_TIME LONGEST_SQ 1 2 3 4 5 ------------- ------ ---------- ---- -------- ----------------------------------- ---------- ------ ------ ----- ---- --- 2spgk3k0f7quz 251 29607 0 546.0 11-04-12 12:11:47 11-04-12 20:25:14 16781748 247 2 0 0 2 990m08w8xav7s 591 7681 0 52.0 11-04-13 00:39:27 11-04-13 02:47:28 16786685 587 0 0 2 2 64dqhdkkw63fd 1083 7147 0 7.0 11-03-07 04:01:01 11-03-07 06:00:08 16777218 1082 0 0 0 1 0bujgc94rg3fj 604 4929 0 25.0 11-04-08 10:53:34 11-04-08 12:15:43 16814628 601 1 1 0 1 0hbv80w9ypy0n 161 4089 0 1184.0 11-03-02 04:36:10 11-04-12 23:34:18 16777290 27 116 9 6 3 bzyny95313u12 114 2599 0 47.0 11-03-03 03:06:18 11-03-03 03:49:37 16781191 113 0 0 0 1 ds8cz0fb8w147 161 2531 13 274.0 11-03-01 23:11:48 11-04-12 16:10:37 16777285 136 18 5 1 1 5k7vccwjr5ahd 2653 1963 0 33.0 11-03-01 23:10:12 11-04-12 09:06:12 16778244 2623 15 8 4 3 4d6m2q3ngjcv9 320 1701 3 485.0 11-03-01 23:10:53 11-04-10 18:01:26 16777261 92 168 50 9 1 g5u58zpg0tuk8 97 1359 1 62.0 11-04-12 02:23:37 11-04-13 02:51:09 16777217 92 3 1 0 1 34cgtc9xkgxny 61 1272 978 1163.0 11-03-02 10:06:24 11-03-02 10:27:36 16777250 4 4 14 30 9 |
Oracle L
Trackbacks
Comments
>> Thanks for the great posts on this topic.
>> I didn’t realize that sql_exec_id had been added to
>> dba_hist_active_sess_history. We have some queries with
>> skewed and this will give us some insight into the variation
>> in execution times for those queries. We had a question about
>> the values that you are passing to width_bucket(). You are
>> passing 0 and mxdelta+.1 for the min_value and max_value parameters,
>> respectively. That results in very skewed histograms in your
>> examples. (There’s 1 row where there aren’t any values in
>> the 1st histogram.) Is there any reason why you are passing
>> those values instead of mndelta and mxdelta?
Good questions. One is easier than the other
1) Why did I use 0 for the min bucket? It was the easiest quickest thing to put for minimum value. A better value would have been the min value ever seen for that query as the starting bucket. I thought about this but never got around to it.
2) Why did I pass in mxdelta+.1 for the max bucket? Well this is a bit of hack that I didn’t look into closely but at least meant to document but forgot to.
With width_bucket, if I ask for 5 buckets I get 2 extra for a total of 7.
The bottom is anything below my minimum, which in this case will always have 0 values as no query should have a negative response time, so I can ignore this bucket. The largest will be anything starting with my largest value on up so if I add a tiny bit to my max value, then this bucket never have values and always be 0 so I can ignore it and I’m back to my 5 buckets.
What if I just asked for 4 buckets instead? Wouldn’t this work? This would give me 6 buckets and I could ignore the first giving me 5 buckets, right?
If I asked for 4 buckets then the fifth bucket would only have single max values in it , ie no range. For the most part this bucket will just have the value 1, unless the exact maximum elapsed time happened more than once. I’d prefer the 5th bucket to actually show a range rather than a single value.
question: how can I find queries that run longer than 5 minutes:
col av for 9999999 col mx for 9999999 col mn for 9999999 select sql_id, count(*), round(min(delta),0) mn, round(avg(delta),0) av, round(max(delta),0) mx, substr(max(times),12) max_run_time from ( select sql_id, sql_exec_id, max(delta) delta , -- lpad sets a fixed width on delta so it can be -- stripped off above with substr -- delta in "times" is just for sorting not displaying lpad(round(max(delta),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 from ( select sql_id, 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 from dba_hist_active_sess_history where sql_exec_id is not null ) group by sql_id,sql_exec_id ) group by sql_id -- incorrectly was -- having mx > 300 -- this is the right syntax having round(max(delta),0) > 300 order by mx /another query – get the CPU, IO and WAIT for sql_ids from dba_hist, ie an AWR repository:
select SQL_ID , sum(decode(session_state,'ON CPU',1,0)) "CPU", sum(decode(session_state,'WAITING',1,0)) - sum(decode(session_state,'WAITING', decode(wait_class, 'User I/O',1,0),0)) "WAIT" , sum(decode(session_state,'WAITING', decode(wait_class, 'User I/O',1,0),0)) "IO" , sum(decode(session_state,'ON CPU',1,1)) "TOTAL" from dba_hist_active_sess_history where SQL_ID is not NULL and dbid=&dbid -- and sample_time between -- to_date('07-NOV-2011 16:00','DD-MON-YYYY HH24:MI') and -- to_date('07-NOV-2011 17:00','DD-MON-YYYY HH24:MI') group by sql_id order by sum(decode(session_state,'ON CPU',1,1)) desc /Your query “how can I find queries that run longer than 5 minutes” is incorrect. This is corrected version.
select
sql_id,
count(*),
round(min(delta),0) mn,
round(avg(delta),0) av,
round(max(delta),0) mx,
substr(max(times),12) max_run_time
from (
select
sql_id,
sql_exec_id,
max(delta) delta ,
— lpad sets a fixed width on delta so it can be
— stripped off above with substr
— delta in “times” is just for sorting not displaying
lpad(round(max(delta),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
from ( select
sql_id,
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
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 round(max(delta),0) > 300
order by mx
/
Updated my comment above yours with the correction. Thanks
@Sandro
Hi sandro, ran into your query/ can you make some sense of these values?
(3600*24) delta
and
having round(max(delta),0) > 300
@Jigar,
Good idea to document the parts of the query.
The (3600*24) is seconds in a day and when subtracting two dates the value you get is the number of days so seconds in a day multiplied by the difference of two dates is the elapsed time between the two dates in seconds.
The “having round(max(delta,0) > 300” looks for queries that ran for more than 5 minutes, ie those queries that were found to have a sample time in ASH greater than 300 seconds higher than the start time of the execution of the query, and 300 seconds if 5 minutes.Could have picked any number instead of 300, but the query was stated as, “find all sql statements that took longer than 5 minutes.