Re: "Elapsed time" from statspack/sql_trace_tkprof_file different;
- From: "Zhu,Chao" <zhuchao@xxxxxxxxx>
- To: daniel.fink@xxxxxxxxxxxxxx
- Date: Wed, 22 Aug 2007 09:43:19 +0800
Thanks to all interested in this.
I should be more precise about the issue;
I will open a Tar for oracle to invetigate and confirm whether this
is a problem caused by trace.
the SQL is a PK based update, so it is predictable that it is always
doing 5-6 buffer_gets per execution. Not likely to have cases of doing
other plan, or jump in cost per execution.
I also dig into the statspack history, for a history of the SQL
execution profile;
here is the data; Here the cpu_per_exec and elapsed_per_exec are all
in unit of 10us;
PARSE BG CPU ELAPSED ROWS
TS EXECS CALLS PER EXEC PER EXEC PER EXEC EXEC
---------- -------- ------ --------- --------- --------- ------ -
0820-03:19 222813 0 5.2 35.58 53.3 1.0
0820-03:34 167564 0 5.2 37.89 50.4 1.0
0820-03:49 204460 0 5.2 36.13 55.6 1.0
0820-04:04 203567 0 5.3 37.48 49.1 1.0
0820-04:19 170175 0 5.3 37.62 59.4 1.0
0820-04:34 220337 0 5.3 35.96 48.3 1.0
0820-04:49 151636 0 5.3 36.41 52.6 1.0
0820-05:04 211118 0 5.2 37.06 52.6 1.0
0820-05:19 164043 0 5.2 36.18 49.2 1.0
0820-05:34 162257 0 5.3 37.19 57.2 1.0
0820-05:49 215841 0 5.3 36.68 49.9 1.0
0820-06:04 131097 0 5.3 37.45 54.2 1.0
0820-06:19 221107 0 5.3 36.72 53.9 1.0
0820-06:34 145441 0 5.3 36.72 50.3 1.0
0820-06:49 192147 0 5.2 36.71 56.1 1.0
0820-07:04 204019 0 5.3 36.08 51.3 1.0
0820-07:19 129494 0 5.3 37.12 57.8 1.0
0820-07:34 209159 0 5.2 36.11 55.5 1.0
0820-07:49 155062 0 5.3 36.88 46.8 1.0
0820-08:04 189890 0 5.2 36.81 55.4 1.0
0820-08:19 202760 0 5.3 36.25 51.2 1.0
0820-08:34 144288 0 5.2 36.32 54.9 1.0
0820-08:49 195798 0 5.3 36.75 52.0 1.0
0820-09:04 158694 0 5.3 37.22 49.8 1.0
0820-09:19 172335 0 5.3 36.42 58.5 1.0
0820-09:34 207706 0 5.3 36.81 49.2 1.0
0820-09:49 129269 0 5.3 36.94 54.6 1.0
0820-10:04 127877 0 5.3 37.81 57.3 1.0
0820-10:19 198044 0 5.3 36.31 55.7 1.0
0820-10:34 167298 0 5.4 37.87 52.0 1.0
0820-10:49 180218 0 5.2 36.56 55.9 1.0
0820-11:04 190218 0 5.3 37.34 53.9 1.0
0820-11:19 157282 0 5.3 36.84 54.6 1.0
0820-11:34 178773 0 5.3 37.16 56.1 1.0
0820-11:49 176890 0 5.4 37.46 51.2 1.0
0820-12:04 185625 0 5.2 36.89 55.6 1.0
0820-12:19 209481 0 5.3 36.18 52.3 1.0
0820-12:34 137303 0 5.3 36.85 56.3 1.0
0820-12:49 210202 0 5.3 36.42 54.4 1.0
0820-13:04 151608 0 5.3 36.49 53.8 1.0
0820-13:19 220423 0 5.2 35.55 54.9 1.0
0820-13:34 201447 0 5.3 37.02 52.2 1.0
0820-13:49 196402 0 5.3 36.77 55.7 1.0
0820-14:04 231267 0 5.3 36.67 49.9 1.0
0820-14:19 198819 0 5.3 36.13 51.1 1.0
0820-14:34 207519 0 5.2 36.46 48.7 1.0
0820-14:49 129090 0 5.3 36.22 44.8 1.0
0820-15:04 50733 0 5.3 36.60 46.1 1.0
0820-17:49 10668 0 5.0 36.18 90.3 1.0
0820-18:04 192704 0 5.2 36.31 50.6 1.0
0820-18:19 218715 0 5.3 36.06 45.4 1.0
0820-18:34 161779 0 5.1 35.16 52.8 1.0
0820-18:49 210999 0 5.3 36.28 45.1 1.0
0820-19:04 181946 0 5.2 36.91 49.3 1.0
0820-19:19 208770 0 5.3 36.60 46.6 1.0
0820-19:34 182426 0 5.3 36.09 48.8 1.0
0820-19:49 197002 0 5.2 35.76 47.1 1.0
0820-20:04 184339 0 5.3 37.02 47.0 1.0
0820-20:19 180865 0 5.2 36.22 49.7 1.0
0820-20:34 213968 0 5.3 36.64 45.7 1.0
0820-20:49 220309 0 5.2 35.78 47.3 1.0
0820-21:04 165317 0 5.3 36.48 46.3 1.0
0820-21:19 213596 0 5.2 36.78 47.8 1.0
0820-21:34 202338 0 5.3 36.46 44.5 1.0
0820-21:49 169135 0 5.2 36.33 49.2 1.0
0820-22:04 207531 0 5.2 36.45 45.0 1.0
0820-22:19 218738 0 5.3 36.69 46.6 1.0
0820-22:34 188148 0 5.2 37.10 46.7 1.0
0820-22:49 211105 0 5.2 35.57 46.5 1.0
0820-23:04 201945 0 5.2 36.50 47.2 1.0
0820-23:19 169503 0 5.2 37.40 45.1 1.0
0820-23:34 206647 0 5.2 36.83 47.8 1.0
0820-23:49 210900 0 5.3 36.14 44.2 1.0
0821-00:04 190950 0 5.1 35.66 46.2 1.0
0821-00:19 221324 0 5.2 36.75 46.2 1.0
0821-00:34 167065 0 5.2 36.78 49.6 1.0
0821-00:49 193609 0 5.2 35.47 49.9 1.0
0821-01:04 178527 0 5.3 36.67 45.8 1.0
0821-01:19 202015 0 5.2 35.82 51.0 1.0
0821-01:34 201078 0 5.2 36.80 46.7 1.0
0821-01:49 203689 0 5.3 36.98 50.9 1.0
0821-02:04 200388 0 5.2 36.17 48.0 1.0
0821-02:19 122295 0 5.2 72.43 84.9 1.0
0821-02:34 182709 0 5.2 37.09 51.2 1.0
0821-02:49 161732 0 5.3 36.30 46.0 1.0
0821-03:04 194406 0 5.2 36.40 51.6 1.0
86 rows selected.
On 8/22/07, Daniel W. Fink <daniel.fink@xxxxxxxxxxxxxx> wrote:
> No, you cannot compare them. You do not know the composition of the
> averages. What is the distribution of the values?
> Example - A sql statement is run. Compare the "sql trace" and
> "statspack" results. 3 of the execs in the Statspack are the ones in the
> SQL trace.
>
> SQL trace - 3 executions, 1 second average (3 execs of 1 second each) (3
> * 1) = 3 / 3 = 1 second average
> Statspack - 30 executions, 3 second average (29 execs of 1 second each,
> 1 exec of 61 seconds for a total of 90 seconds) (29 * 1) + (1 * 61) = 90
> / 30 = 3 second average
>
> Or
>
> SQL trace - 3 executions, 21 second average (2 execs of 1 second each, 1
> exec of 61 seconds). (2 * 1) + (1 * 61) = 63 / 3 = 21 second average
> Statspack - 30 executions, 3 second average (29 execs of 1 second each,
> 1 exec of 61 seconds for a total of 90 seconds) (29 * 1) + (1 * 61) = 90
> / 30 = 3 second average
>
> Granted, this is an extreme case (well, not all that extreme considering
> some performance I have seen), but it illustrates that you cannot
> absolutely compare a subset with a whole.
>
> --
> Daniel Fink
>
> Oracle Performance, Diagnosis and Training
>
> OptimalDBA http://www.optimaldba.com
> Oracle Blog http://optimaldba.blogspot.com
>
>
> Zhu,Chao wrote:
> > I am comparing per Execution cost/elapsed time.
> > Total elapsed time / total executions = per execution cost. they are
> > comparable.
> >
> > On 8/22/07, Allen, Brandon <Brandon.Allen@xxxxxxxxxxx> wrote:
> >
> >> Assuming your stats below are for the same query, your tkprof is only
> >> accounting for 32945 executions while the statspack is accounting for
> >> almost 1 million executions so you're not comparing apples to apples.
> >>
> >> Regards,
> >> Brandon
> >>
> >>
>
>
--
Regards
Zhu Chao
www.cnoug.org
--
//www.freelists.org/webpage/oracle-l
Other related posts:
