Re: Times do not add up in 10046 trace file

On Mon, 06 Nov 2006 17:17:40 +0100, t c p r o f @ t o l a n . f r wrote:

>On 11 Oct 2006 03:13:17 -0700, mccmx_at_hotmail.com wrote:
>
>>Oracle 10.2.0.2 W2K3
>>
>>In the summary section of the trace file below, the total elapsed time
>>is 113.84s of which 72.12s seconds was CPU time. This leaves 41s of
>>wait time. However the wait breakdown adds up to much more than this.
>>Ignoring SQL*Net wait times because they are 'between call' waits, we
>>have at least, 63.15 + 33.10 + 3.91 = 100.16.
>>
>>Can anyone explain why the total wait time is so much higher than the
>>difference between CPU and elapsed times....?
>>
>>********************************************************************************
>>
>>OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
>>
>>call count cpu elapsed disk query current
>> rows
>>------- ------ -------- ---------- ---------- ---------- ----------
>>----------
>>Parse 10675 8.39 12.22 0 3 0
>> 0
>>Execute 57732 36.50 57.10 100129 101923 165840
>> 27507
>>Fetch 53336 27.23 44.51 101400 1213121 0
>> 53250
>>------- ------ -------- ---------- ---------- ---------- ----------
>>----------
>>total 121743 72.12 113.84 201529 1315047 165840
>> 80757
>>
>>Misses in library cache during parse: 8083
>>Misses in library cache during execute: 8269
>>
>>Elapsed times include waiting on following events:
>> Event waited on Times Max. Wait Total
>>Waited
>> ---------------------------------------- Waited ----------
>>------------
>> SQL*Net message to client 105456 0.00
>> 1.14
>> SQL*Net message from client 105456 0.02
>>239.01
>> db file sequential read 888 0.10
>> 3.91
>> db file scattered read 12701 0.15
>>33.10
>> log file sync 13940 0.03
>>63.15
>> undo segment extension 11 0.00
>> 0.00
>> latch: library cache 3 0.00
>> 0.00
>> latch: shared pool 14 0.00
>> 0.00
>> latch free 8 0.00
>> 0.01
>> latch: redo allocation 2 0.00
>> 0.00
>> latch: cache buffers chains 1 0.00
>> 0.00
>> latch: row cache objects 1 0.00
>> 0.00
>
>
>
>I've recently made a profiler available on the net. It's spent 8
>months in development and a handful of testers and I have used it to
>analyse some 100 or so 10046 trace files with a great deal of success.
>I've put the profiler on the web for public beta testing - for which
>you will have to register. If you'd be interested in running your
>trace file thru the profiler point your web browser at
>http://tcprof.tolan.fr
>
>It does: -
>
>o full response time accounting, so you should find out where all
>your time went.
>
>o it produces a resource profile so you can easily see where your
>time was spent on task
>
>o you get a breakdown of SQL by subroutine that allows you to find
>which pieces of SQL are responsible for motivating the subroutines
>that eat up all your time. This means you can focus your efforts on
>fixing what really matters
>
>o naturally each SQL statement decomposed into individual actions,
>parse, exec, fetch, waits etc with full response time accounting so
>once again you should be able to find what's wrong.
>
>o finally there is a full database call SQL parent/child tree so you
>know why individual pieces of SQL are called.
>
>I should probably mention that I've tested it (using a few trace
>files) against the market leaders in this field and I get pretty much
>the same results - within 1% - so I am very confident if you submit a
>properly scoped trace file you'll get accurate results.!
>
>At present, I'm working on a paper to explain the output and work
>through an example discussing how to use it and what it all means -
>this should be on the net in the next few days.
>
>Hope this helps
>
>Tom Churchward.
>
>PS. web site isn't too pretty I'm afraid as I've been focussing on get
>the profiler up to a level for public beat along with the
>documentation...

I mentioned in my last post on this thread that I was working to produce a paper to explain and work thru an example of tcprof usage... A bit later than anticipated, I'm pleased to say the document is ready. If you are interested please point your web browser at http://tcprof.tolan.fr and head for the page marked 'papers'. Comments, feedback, suggestions etc. welcomed.

Best regards

Tom Churchward Received on Thu Nov 23 2006 - 06:56:44 CST