Re: Times do not add up in 10046 trace file

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... Received on Mon Nov 06 2006 - 10:17:40 CST