Re: elapsed time less cpu time???

From: Ed Stevens <nospam_at_noway.nohow>
Date: Fri, 14 Nov 2003 15:14:59 -0600
Message-ID: <ftgarvs4v4hgt16rbj6gshabo3q9krgdem@4ax.com>

The 20,000 rows is actually the entire table.

See my response to Jonathan for "the rest of the story", re: stats and FTS. As for the 6600 reads, I've never know what would be considered a "good" ratio, or if there even is a good rule. Now, I wouldn't have any trouble seeing that, say 1,000,000 reads for 1 row is pretty excessive and 1 read for 1 row is probably impossibly good, but somewhere in the middle . . . ????

Here's what happened after gathering stats:

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ----------

---

Parse 1 0.01 0.01 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 1335 0.28 0.27 0 1566 0 20000
------- ------ -------- ---------- ---------- ---------- ----------

---

total 1337 0.29 0.28 0 1566 0 20000

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 5

Rows Row Source Operation

-------  ---------------------------------------------------

  20000 TABLE ACCESS FULL POSTED_SUMMARY On 14 Nov 2003 11:25:44 -0800, amolinaro_at_wgen.net (anthony) wrote:

>Ed,
> I think the time descrepancy is due to how the db/os gathers the
>timing stats during a trace. From my experience it's just a "blip" and
>not a sign of a problem. If cpu was lower than elapsed, then i'd say
>your sql was waiting on some resource.
>The query seems fast enough, but i'd take a look at those reads, 6600
>for 20,000 rows? How big is the table? Are the stats up to date?
>What's the performace like using a full scan?
>
> - ant
>
>Ed Stevens <nospam_at_noway.nohow> wrote in message news:<k0t9rv0768incjhidb5ear4jmdplrek2da_at_4ax.com>...
>> Oracle 9.2 on Solaris 9
>>
>> In response to a developer's complaint that a query suddenly went
>> south, I ran the query w/ sql_trace=true then fed the resulting trace
>> file to TKPROF. An interesting result was that on the fetch phase,
>> the cpu time was 0.51 seconds, while the elapsed time was 0.44 sec.
>> Sonds like a house that's bigger on the inside than on the outside.
>>
>> Here's the TKPROF report. Sorry about the line wraps. If someone can
>> tell me how to prevent that, as well, I'd be grateful. (I'm using Free
>> Agent as my newsreader)
>>
>> The rest of the report, including the access plan, looks pretty good
>> to me. If someone wants to disabuse me of that notion, I won't mind
>> being further educated.
>>
>>
>> TKPROF: Release 9.2.0.1.0 - Production on Fri Nov 14 08:16:37 2003
>>
>> Copyright (c) 1982, 2002, Oracle Corporation. All rights reserved.
>>
>> Trace file: cmdm1240_ora_13714.trc
>> Sort options: default
>>
>> <snip>
>> ********************************************************************************
>>
>> select POSTED_NAME,
>> WORK_ORDER_NUMBER,
>> SITE_ID,
>> GL_ACCOUNT,
>> WBS_ELEMENT,
>> COST_CENTER,
>> SUMMARY_COST,
>> TOTAL_COST
>> from NMM.POSTED_SUMMARY
>> where POSTED_NAME = 'TESTPOST'
>> AND POSTED_CODE = 'F'
>>
>> call count cpu elapsed disk query current
>> rows
>> ------- ------ -------- ---------- ---------- ---------- ----------
>> ----------
>> Parse 1 0.00 0.01 0 0 0
>> 0
>> Execute 1 0.00 0.00 0 0 0
>> 0
>> Fetch 1335 0.51 0.42 0 6613 0
>> 20000
>> ------- ------ -------- ---------- ---------- ---------- ----------
>> ----------
>> total 1337 0.51 0.44 0 6613 0
>> 20000
>>
>> Misses in library cache during parse: 1
>> Optimizer goal: CHOOSE
>> Parsing user id: 5
>>
>> Rows Row Source Operation
>> ------- ---------------------------------------------------
>> 20000 TABLE ACCESS BY INDEX ROWID POSTED_SUMMARY
>> 20000 INDEX RANGE SCAN PK_POSTED_SUMMARY (object id 23873)
>>
>> ********************************************************************************
>> <snip>
Received on Fri Nov 14 2003 - 15:14:59 CST