Re: How to understand trace result

From: Nigel Thomas <nigel.cl.thomas_at_googlemail.com>
Date: Sat, 10 Jan 2009 15:48:47 +0000
Message-ID: <53258cd50901100748p4bf3ce13we4a7e62b4822c189_at_mail.gmail.com>

>   OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS


>>

>> call     count       cpu    elapsed       disk      query

>> current        rows

>> ------- ------ -------- ---------- ---------- ---------- ----------
>> ----------
>> Parse 0 0.00 0.00 0 0
>> 0 0
>> Execute 0 0.00 0.00 0 0
>> 0 0
>> Fetch 0 0.00 0.00 0 0
>> 0 0
>> ------- ------ -------- ---------- ---------- ---------- ----------
>> ----------
>> total 0 0.00 0.00 0 0
>> 0 0
>>
>> Misses in library cache during parse: 0
>>
>>
>> OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
>>
>> call count cpu elapsed disk query
>> current rows
>> ------- ------ -------- ---------- ---------- ---------- ----------
>> ----------
>> Parse 280247 7.17 6.92 0 736
>> 6 0
>> Execute 838921 72.83 74.21 272 79225 10914
>> 10758
>> Fetch 841865 619.19 629.54 136 7889481 1
>> 842533
>> ------- ------ -------- ---------- ---------- ---------- ----------
>> ----------
>> total 1961033 699.21 710.68 408 7969442 10921
>> 853291
>>
>> Misses in library cache during parse: 211
>> Misses in library cache during execute: 170
>>
>> Elapsed times include waiting on following events:
>> Event waited on Times Max. Wait Total
>> Waited
>> ---------------------------------------- Waited ----------
>> ------------
>> db file sequential read 278 0.05
>> 1.73
>> latch: library cache 15 0.00
>> 0.00
>> latch: shared pool 10 0.00
>> 0.00
>> undo segment extension 1 0.00
>> 0.00
>> db file scattered read 10 0.02
>> 0.09
>> log file sync 1 0.00
>> 0.00
>> reliable message 3 0.00
>> 0.00
>> rdbms ipc reply 3 0.01
>> 0.02
>> enq: RO - fast object reuse 2 0.00
>> 0.00
>> latch: row cache objects 1 0.00
>> 0.00
>>
>> 279017 user SQL statements in session.
>> 2835 internal SQL statements in session.
>> 281852 SQL statements in session.
>>

>
Further to Toon's comments, note:

• that all time is apparently spent in recursive SQL - and *none* of it from a direct client call (presumably any client call hasn't finished in the 5 minute period)
• number of physical reads is trivial - that's a fantastic buffer hit ratio - around 1/20k buffer miss which makes 99.98% hit ratio if my weekend math is correct :-). Or to put it another way, each data block is accessed 20,000 times which seems excessive (again, a badly written application).

Back to the OPs question - what do the numbers mean? If this question is literal (as opposed to "how should I interpret these results) then see the writeup in http://www.oracleutilities.com/OSUtil/tkprof.html. Or RTFM.

Regards Nigel

--
http://www.freelists.org/webpage/oracle-l

Received on Sat Jan 10 2009 - 09:48:47 CST