Tkprof interpretation !

Chris Fung — Tue, 21 Jan 2003 12:16:24 GMT

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,

Re: Tkprof interpretation !

Yogeeraj_1 — Tue, 21 Jan 2003 12:58:02 GMT

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

Re: Tkprof interpretation !

Yogeeraj_1 — Tue, 21 Jan 2003 13:01:28 GMT

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

Regards
Yogeeraj

Re: Tkprof interpretation !

Chris Fung — Thu, 23 Jan 2003 04:15:27 GMT

Hi Yogeeraj,

Thanks your your detailed explanation.

Very helpful to me !!!

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

Cheers,

Chris,

topic Re: Tkprof interpretation ! in Operating System - HP-UX

Tkprof interpretation !

Re: Tkprof interpretation !

Re: Tkprof interpretation !

Re: Tkprof interpretation !