SQL timings for ASH II
May 6th, 2011
- 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/
Here is a max, min, avg execution time for SQL executions in ASH data along with count of execution and histogram of their execution times
(tomorrow I’ll look at showing the execution date time of the longest elapsed times)
col 1 for 99999
col 2 for 99999
col 3 for 9999
col 4 for 9999
col 5 for 9999
col av for 99999.9
with pivot_data as (
select
sql_id,
ct,
mxdelta mx,
mndelta mn,
avdelta av,
width_bucket(delta,0,mxdelta+.1,5) as bucket
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
from (
select
sql_id,
sql_exec_id,
max(delta) delta
from ( select
sql_id,
sql_exec_id,
((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
)
)
)
select * from pivot_data
PIVOT ( count(*) FOR bucket IN (1,2,3,4,5))
order by mx,av
/
|
SQL_ID CT MX MN AV 1 2 3 4 5 ------------- ---------- ---------- ---------- -------- ------ ------ ----- ----- ----- 5k7vccwjr5ahd 2653 1963 0 33.4 2623 15 8 4 3 ds8cz0fb8w147 161 2531 13 273.8 136 18 5 1 1 bzyny95313u12 114 2599 0 46.5 113 0 0 0 1 0hbv80w9ypy0n 161 4089 0 1183.9 27 116 9 6 3 71fwb4n6a92fv 49 4481 30 676.9 38 6 2 2 1 0bujgc94rg3fj 604 4929 0 24.7 601 1 1 0 1 64dqhdkkw63fd 1083 7147 0 7.2 1082 0 0 0 1 990m08w8xav7s 591 7681 0 51.8 587 0 0 2 2 2spgk3k0f7quz 251 29607 0 546.1 247 2 0 0 2 497wh6n7hu14f 49 69438 0 5498.2 44 1 0 1 3 |
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.
Hi Kyle, One question:
Are the columns MX,MN,AV showing values in seconds or millisecond????
I am getting the below stats for one of my sql id:
SQL_ID CT MX MN AV 1 2 3 4 5
————- ———- ———- ———- ——– —— —— —– —– —–
7xzf09srjz3gu 1756 2 0 1.1 190 0 1263 0 303
Which means that maximum time for any execution is 2 seconds??
From v$sql i see below stats.As far as i know any execution time for this sql won’t be more than a second.
Buffer Disk Gets CPU Eleapsed IO App
SQL Buffer Disk Rows Cache Gets Reads Per Time Time Wait Wait
Id PHV CHNO Exec gets Reads Proc Ratio per Exec per Exec Row Per Exec(ms) Per Exec(ms) Per Exec(ms) Per Exec(ms)
————— ———- ———- ———- ————- ————- ———– ——- —————- —————- ———– ————- ————- ———— ————
Avg
Slaves Direc
Per Exec Write
——— ———-
7xzf09srjz3gu 2560245071 0 1 15 0 0 100.00 15.00 .00 15 10.00 58.59 0 0
0 0
7xzf09srjz3gu 1463930066 1 7576456 90270307 11546542 3531964 87.21 11.91 1.52 26 .64 16.26 16 0
0 0
The same trend is seen for any sql id. So are you saying that for some execution the execution time was indeed approximately 2 seconds??
Hi Kunwar, yes the ASH output says your query ran more than 1 second at some point. It looks like from the to me that your query ran
under 1 second 190 times
over 1 second 1263 times
over 2 seconds 303 times
for an average of 1.06 seconds based on statistical sampling
As far as the output from v$sql, I’m having trouble reading it because of the formatting in the comment.
@Kyle Hailey
Kyle,
Below is the query i am using the get the stats from v$sql and all i wanted to show was i was getting Elapses/exec of 58.59 ms and 16.26 ms for childs 0 and 1 .
But the data from ASH shows very high figures.
set lines 200
set pages 50000
set trimspool on
col module head “Module” for a8 trunc
col sql_id head “SQL|Id” for a15
col executions head “Exec” for 999999999
col buffer_gets head “Buffer|gets” for 999999999999
col gpere head “Buffer|Gets|per Exec” for 999999999999.99
col dread head “Disk|Reads” for 999999999999
col ppere head “Disk|Reads|per Exec” for 999999999999.99
col rproc head “Rows|Proc” for 9999999999
col gperw head “Gets|Per|Row” for 9999999999
col loads head “Tot|Load” for 9999
col invalidations head “Tot|Inva” for 9999
col cputs head “CPU|Time|Per Exec(ms)” for 999999999.99
col elat head “Eleapsed|Time|Per Exec(ms)” for 999999999.99
col iwait head “IO|Wait|Per Exec(ms)” for 99999999
col await head “App|Wait|Per Exec(ms)” for 99999999
col ccwait head “Conc|Wait(ms)” for 9999999
col slaves head “Avg|Slaves|Per Exec” for 99999999
col dwait head “Direc|Write” for 999999999
col snpdt head “Snap|Date” for a8
col cratio head “Cache|Ratio” for 999.99
SELECT s_hist.*
FROM
(
SELECT
dst.sql_id sql_id,
dst.plan_hash_value phv,
dst.child_number chno,
dst.executions executions,
dst.buffer_gets buffer_gets,
dst.disk_reads dread,
dst.rows_processed rproc,
(1-dst.disk_reads/decode(dst.buffer_gets,0,1,dst.buffer_gets))*100 cratio,
round((dst.buffer_gets/decode(dst.executions,0,1,dst.executions)),2) gpere,
round((dst.disk_reads/decode(dst.executions,0,1,dst.executions)),2) ppere,
round((dst.buffer_gets/decode(dst.rows_processed,0,1,dst.rows_processed)),2) gperw,
((dst.cpu_time)/1000)/decode(dst.executions,0,1,dst.executions) cputs,
((dst.elapsed_time)/1000)/decode(dst.executions,0,1,dst.executions) elat,
((dst.user_io_wait_time)/1000)/decode(dst.executions,0,1,dst.executions) iwait,
((dst.application_wait_time)/1000)/decode(dst.executions,0,1,dst.executions) await,
((dst.px_servers_executions))/decode(dst.executions,0,1,dst.executions) slaves,
dst.direct_writes dwait
FROM
v$sql dst
WHERE dst.sql_id = ‘&1’
) s_hist
/
@Kuwar: the above query is just the averages. It doesn’t tell you max and min executions nor when the max and min happened for example. The query on http://dboptimizer.com/2011/05/06/sql-ash-timings-iii/ will show you when the maximum execution happened for example. Unfortunately it doesn’t give the bind variables at the time of the slowest execution, but for queries that take more than a second it can provide a better picture than the simple averages.
@Kuwar: also using the sql_exec_id from the longest execution you can go back into ASH and see where the query was spending it’s time