Re: elapsed time less cpu time???

From: Jonathan Lewis <jonathan_at_jlcomp.demon.co.uk>
Date: Fri, 14 Nov 2003 16:10:14 -0000
Message-ID: <bp2umh$tb$1$8300dec7@news.demon.co.uk>

If you look at the trace file you will find that elapsed time is reported in microseconds, but cpu time is reported with a granularity of 1/100 sec, which is then faked into micro seconds - The figures will all be multiples of 10,000 (perhaps with with a value like 17 added to confuse the issue).

So CPU times will be zero on may lines, and then 10,000 on one line - whilst the ela might run at a steady few hundred per line. The final result is probably due to rounding errors across the 1,335 fetches that are recorded.

50,000 rows per second seems quite reasonable to me - I bet your developer can't read them that quickely ;)

--
Regards

Jonathan Lewis
http://www.jlcomp.demon.co.uk

  The educated person is not the person
  who can answer the questions, but the
  person who can question the answers -- T. Schick Jr


One-day tutorials:
http://www.jlcomp.demon.co.uk/tutorial.html
____Belgium__November (EOUG event - "Troubleshooting")
____UK_______December (UKOUG conference - "CBO")


Three-day seminar:
see http://www.jlcomp.demon.co.uk/seminar.html
____UK___November


The Co-operative Oracle Users' FAQ
http://www.jlcomp.demon.co.uk/faq/ind_faq.html


"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 - 10:10:14 CST