Re: Why is time_waited more than total elapsed time ?

It would help if you gave the Oracle version. One possible answer is granularity of measurement.

I understand that the more recent versions of 8.1 measure time in microseconds, but report it in centi-seconds. In sql_trace, the time per wait is always rounded to centiseconds - so you are summing something which has been rounded, and the rounding could well have rounded to zero.

In v$system_event, the time is not rounded on each event, it is only rounded when you report it.

Consequently your total time recorded in v$system_event can vary quite dramatically from the total time recorded in v$system_event.

Interestingly, though, given that you are running a single controlled session, the number of reads in v$system event if 5,000 higher than the reads in the trace file. Of course, we wouldn't really expect 6% extra reads to make a 30% difference in total time - but it is possible.

Better let us know the platform as well as the version where v$system_event can show time when v$session_event is show zeros. Is it possible that a login trigger could set timed_statistics = false whilst timed_statistics was still true at the system level ? I don't think so - but haven't checked it. (I know the converse is true, and can produce some very misleading results).

--
Jonathan Lewis
http://www.jlcomp.demon.co.uk

Next Seminars
        UK            July / Sept
        Australia      July / August
        Malaysia        September
        USA (MI)        November
http://www.jlcomp.demon.co.uk/seminar.html

Bass Chorng wrote in message ...


>I am wondering why my time_waited on 'db file sequential read' is MUCH more

>than my total elapsed time in tkprof.

>

>I ran a long query in a controlled test enrivornment ( no other session

running)


>and the query was executed right after a fresh bounce

>

>Here is the tkprof result of it:

>

>call     count       cpu    elapsed       disk      query    current

rows


>------- ------  -------- ---------- ---------- ---------- ----------  -----

-----


>Parse        1      0.04       0.09          1         18          0

0


>Execute      1      0.00       0.00          0          0          0

0


>Fetch     5807     21.94     296.24      76109     376395         37

87091


>------- ------  -------- ---------- ---------- ---------- ----------  -----

-----


>total     5809     21.98     296.33      76110     376413         37

87091


>

>

>Note here that my elased time is 296.33 seconds.

>

>At the same time, I also trapped the difference of v$system_event

>before and after the run, and here is the result:

>

>TIMESTAMP           EVENT                               TOTAL_WAITS

TIME_WAITED


>------------------- ----------------------------------- ----------- -------

----


>2002/06/20 10:02:44 db file sequential read                   80962

41924


>2002/06/20 10:02:44 db file scattered read                      291

1264


>

>Note here that my sequential read is 419.24 seconds.

>

>There are nothing else running and this is only a single session query.

>My parallel_min_servers is set to 0 and there is no hint in this query

>to tell Oracle to use parallel query.

>

>I thought the elased time (roughtly) = CPU time + event wait time.

>But this completely confuses me. Can anyone please explain this ?

>

>Thanks in advance.

>

>-bass

>

>BTW, the reason I trap the diff before and after on v$system_event, instead

of


>using v$session_event, is the latter showed all zero, so the data is

useless -


>maybe another question for those who know why.