Tkprof interpretation !

[Chris Fung]

Hi all,

I collected sql_trace statistics and use tkprof to format the trace report. However I have some doubt about the meaning of elapsed time ?? Any idea ? What is the relationship between cpu and elapsed time? What are their significant in determinining the performance of the sql statement ?

Appreciated for your comments.

Many thanks,

Chris Fung,

[Yogeeraj_1 · Accepted solution]

hi,

CPU - In CPU seconds, how much time was spent on this phase of the query execution. This is only filled in if TIMED_STATISTICS are enabled.

ELAPSED - As measured by the wall clock; how long this phase of query execution took. This is again only filled in if TIMED_STATISTICS are enabled.

Let us see a tkprof that shows you things like:

---------------------------------------------------------
update emp set ename = ename


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.01 39.04 0 19 16 14
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.01 39.04 0 19 16 14

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 241

Rows Row Source Operation
------- ---------------------------------------------------
0 UPDATE
14 TABLE ACCESS FULL OBJ#(36120)


so apparently, that took 0.01 cpu seconds yet it took 39.04 seconds by the wall clock. The end user waited AT LEAST 39.04 seconds for that result to be returned -- maybe more (that is your Y above -- 39.04, you need the X to compute whether the server or client is the bottleneck)


Now, since I have 9i we get the wait events in the tkprof as well, they are separate and distinct from ELAPSED times:

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
enqueue 14 2.99 39.03
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************

here we see the database, during the processing of this statement waited on an enqueue (a LOCK -- i locked all rows in emp in another session first). It timed out 14 times and went back and waited again. That cumulative time -- 39.03 seconds -- accounts for the difference between the CPU time above and the ELAPSED time. If we wait for nothing -- cpu and elapsed are the same, if we wait for some resource - they will differ.



Hope this helps!

Best Regards
Yogeeraj

[Yogeeraj_1]

hi again,
sorry for the output problem.
posting the reply in the attached text file

Regards
Yogeeraj

[Chris Fung]

Hi Yogeeraj,

Thanks your your detailed explanation.

Very helpful to me !!!

I am very appreciated. Think that you probably an "OCM" !!

Cheers,

Chris,