elapsed time less cpu time???

From: Ed Stevens <nospam_at_noway.nohow>
Date: Fri, 14 Nov 2003 09:36:37 -0600
Message-ID: <k0t9rv0768incjhidb5ear4jmdplrek2da@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

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 - 09:36:37 CST