Re: help with reading tkprof output

From: bugbear <bugbear_at_trim_papermule.co.uk_trim>
Date: Thu, 15 Nov 2007 13:50:41 +0000
Message-ID: <13jojlhmgijksb5@corp.supernews.com>

sybrandb wrote:

> On Nov 15, 1:06 pm, bugbear <bugbear_at_trim_papermule.co.uk_trim> wrote:

>> Under Oracle 10g (10.2.0.3.0)
>>
>> I have a tkprof log.
>>
>> The plan appears perfectly sensible,
>> and the fetch runs very rapidly.
>>
>> The time for the "fetch" phase is nicely documented
>> against the plan, with time in us for each part
>> of the evaluation.
>>
>> But all this detail applies to the "fetch".
>>
>> Sadly, most of the user and elapsed time is going
>> in "Excute":
>>
>> call count cpu elapsed disk query current rows
>> ------- ------ -------- ---------- ---------- ---------- ---------- ----------
>> Parse 1 0.01 0.00 0 0 0 0
>> Execute 1 12.91 12.61 0 0 0 0
>> Fetch 3 0.05 0.04 0 1634 0 26
>> ------- ------ -------- ---------- ---------- ---------- ---------- ----------
>> total 5 12.97 12.67 0 1634 0 26
>>
>> for which I have no "finer grained" information.
>>
>> So; two questions;
>>
>> what activities does tkprof group under "Execute" and how can I get
>> finer grained information on them?
>>
>> Thanks to all for any help provided.
>>
>> BugBear

> 
> Execute usually means 'sort'.
> As you don't post the execution plan, I can not confirm this.

Sorry; a sort is (indeed) the outermost process in the plan, but with a total time of only 44595 us, (44 millisec, or .04 sec) which sits nicely with the fetch time.

Rows Row Source Operation

-------  ---------------------------------------------------
      26  SORT ORDER BY (cr=1634 pr=0 pw=0 time=44595 us)
      26   FILTER  (cr=1634 pr=0 pw=0 time=44753 us)
      26    NESTED LOOPS OUTER (cr=1634 pr=0 pw=0 time=44716 us)
      26     NESTED LOOPS OUTER (cr=1557 pr=0 pw=0 time=42958 us)
      26      NESTED LOOPS OUTER (cr=1478 pr=0 pw=0 time=41380 us)

.

.
.

    BugBear Received on Thu Nov 15 2007 - 07:50:41 CST