Thanks for the question, Dan.

Asked: May 31, 2007 - 12:29 pm UTC

Last updated: June 06, 2007 - 1:08 pm UTC

Version: 10.2.0.3

Viewed 10K+ times! This question is

You Asked

Hi my prefered Guru,

How can we explain the big difference between cpu=122.20 and elapsed=949.20
for an:

INSERT into PS_JRNL_LN_TMP 
select ... from PS_JRNL_LN A, PS_JRNL_HDR_TMP T WHERE ...

Can be 'recursive SQL statements' an explanation for the only 122 rows inserted?

call     count       cpu    elapsed       disk      query current     rows
------- ------  -------- ---------- ---------- ---------- -------  -------
Parse        0      0.00       0.00          0          0       0        0
Execute      1    122.20     949.20     705989    2247183      44      122
Fetch        0      0.00       0.00          0          0       0        0
------- ------  -------- ---------- ---------- ---------- -------  -------
total        1    122.20     949.20     705989    2247183      44      122

Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 28  (SYSADM)

Rows     Execution Plan
-------  ---------------------------------------------------
      0  INSERT STATEMENT   MODE: ALL_ROWS
      0   TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF 'PS_JRNL_LN' 
              (TABLE)
      0    NESTED LOOPS
      0     INDEX   MODE: ANALYZED (SKIP SCAN) OF 'PS_JRNL_HDR_TMP' 
                (INDEX (UNIQUE))
      0     INDEX   MODE: ANALYZED (RANGE SCAN) OF 'PSEJRNL_LN' (INDEX)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                     68572        0.30         66.79
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1        0.00          0.00
  SQL*Net more data from client                   1        0.00          0.00
********************************************************************************

Thank you for your time and brain

and Tom said...

wow, 2,247,183 IOs to get.....

122 rows. that is sad.

Probably someone has hinted this to death to use indexes and that is so wrong for this query. Probably full scans and hash joins would be right.

http://asktom.oracle.com/pls/asktom/f?p=100:11:0::::P11_QUESTION_ID:6749454952894#6760861174154

now, looks like tracing was turned on AFTER this started .... so the numbers are questionable.

705,989 physical reads would almost certainly cause more than 68,572 IO waits - so I question that number.

Also, if you were CPU starved, then you would see cpu < elapsed without any waits at all (eg: if it takes you 60 seconds to get 10 cpu seconds of runtime - you'll have cpu=10, ela=60 and no waits - since the wait was really to get onto the cpu)

Rating

(10 ratings)

Is this answer out of date? If it is, please let us know via a Comment

Comments

A reader, May 31, 2007 - 4:46 pm UTC

705,989 physical reads would almost certainly cause more than 68,572 IO waits - so I question that number.

What should be a reasonable number for IO waits then in this case ?

June 01, 2007 - 8:20 am UTC

705,989

I would expect all physical IO to incur a measurable wait event. IO is "glacial" in computer speed.

what I mean here is - you turned on tracing mid stream and probably turned it off before it was done...

A reader, June 01, 2007 - 1:27 pm UTC

Also, if you were CPU starved, then you would see cpu < elapsed without any waits at all (eg: if it takes you 60 seconds to get 10 cpu seconds of runtime - you'll have cpu=10, ela=60 and no waits - since the wait was really to get onto the cpu)

Could not understand the above statement. Can you pls elaborate a bit - thanks

June 01, 2007 - 1:35 pm UTC

say you have 100 people concurrently executing:

for i in 1 .. 1000000
loop
y := ln(i);
end loop;

say that it takes 5 cpu seconds for that to execute (just assume that it does)

so, 100 users * 5 cpu seconds = 500 cpu seconds.

Suppose you have a single cpu machine, in order to get 500 cpu seconds of runtime, we need 500 seconds of ELAPSED time.

If all 100 run at the same time, all 100 finish at about the same time - all 100 users observe "500 seconds of elapsed time", but they only each use 5 cpu seconds.

so, a tkprof would have 5 cpu seconds, 500 elapsed seconds - with no external wait events.

Suppose you have a 2 cpu machine, same scenario. Now to get 50 cpu seconds, we need 250 elapsed seconds - so .....

and so on.

A reader, June 01, 2007 - 3:03 pm UTC

If all 100 run at the same time, all 100 finish at about the same time - all 100 users observe "500 seconds of elapsed time", but they only each use 5 cpu seconds.

But this cpu dumping happens only for statspack reports - right ?

Whatever CPU number reported in a tkprof report is for an application, I thought - not for the entire db ?

In a tkprof report, CPU times reported is only for that session which was traced/tkprofed

June 03, 2007 - 5:01 pm UTC

this is not cpu dumping, this is MATH

I'll try again....

you run something that takes 1 cpu second to execute.

you are on a single cpu machine (it can give you 1 cpu second per wall clock second)

Actually - you and FOUR of your friends are doing this and you all hit "enter" at the same time.

So, simultaneously - you ask the computer for 1 cpu second each - a total of 5 cpu seconds....

On this single cpu machine, in order to serve up 5 cpu seconds, we need AT LEAST 5 elapsed seconds of time.

Due to the time slicing nature of the operating system scheduler - each of you runs a bit, then sleeps waiting for the cpu then runs then sleeps and so on.

5 seconds later - all five of you finish. You each consumed 1 cpu second (sql_trace would show this, whatever). You each needed to wait 5 ELAPSED seconds to get this one cpu second.

That is a way to have elapsed > cpu without observing any "waits" in a tkprof - if you have to "wait" for the cpu, that is not a "wait" in the classic sense like a wait for IO is - we do not track the time you tried to be on the cpu and could not be on the cpu.... that would only show itself as a difference between cpu and elapse

Write Consistency ?

Yogesh Purabiya, June 02, 2007 - 7:22 am UTC

Can this be because of some parallell updates of the rows selected by WHERE Clause and thus causing the insert to restart ?

June 03, 2007 - 5:37 pm UTC

can what?

CPU time Vs elapsed time

A reader, June 04, 2007 - 3:02 pm UTC

Thanks for the clear explanation

So in those types of scenarios - the significant difference between CPU and elapsed times could be due to CPU waits - which does not show up anywhere in a tkprof report

btw - is this CPU waits reported in 10g statspack reports ?

thanks
Apraim

June 06, 2007 - 12:26 pm UTC

when you are waiting on cpu, you are in LIMBO from anyones perspective, you are not doing anything you can "time"

Write Consistency ?

Yogesh Purabiya, June 04, 2007 - 11:27 pm UTC

2,247,183 IOs to get..... 122 rows.

If there is a before insert trigger on PS_JRNL_LN_TMP which in turn modifies the table PS_JRNL_LN (and commits it - autonomos transaction), the insert would restart. Since insert does not need to aquire locks on the rows selected, this can happen several times for a single insert statement. Am I right ?

June 06, 2007 - 12:48 pm UTC

did you try it? to find out if "you are right"?

but the insert would not restart. we restart when we found a row in read consistent mode (like an UPDATE or a DELETE 'finds' a row) and discover that the current mode version of the row is different from our consistent read version.

We are not modifying existing rows when we insert, we create new. So there is no read consistent version to compare to a current mode version.

could wait on the remote db

Sean, June 05, 2007 - 1:51 am UTC

if the query involving remote db(s) via db link(s), it could be the wait time on the remote queries complete..

June 06, 2007 - 12:50 pm UTC

why do you say that?

CPU time

A reader, June 05, 2007 - 11:54 am UTC

The fact that CPU time is reported only when the job completes - is that true for sql_Trace/tkprof as well ? ( I know that is the case with statspack reports)

June 06, 2007 - 1:08 pm UTC

cpu time is emitted in the trace file for various discrete operations. if you look at a raw trace file, you'll see cpu being spit out on many of the lines over time.

and because of that, the cpu time reported by tkprof can be different from the aggregate time!

start_cpu = get_cpu_time_now
loop a lot of
times
start_cpu2 = get_cpu_time_now
do something
used_cpu = get_cpu_time_now-start_cpu2
write trace record with used_cpu
end loop
used_cpu = get_cpu_time_now - start_cpu
report out used_cpu

when you measure a discrete operation lots of times using a clock that has a finite precision (like 1/100th or 1/1000th of a second - the cpu clock), errors creep in as each observation could be off by + or - 1/100th or 1/1000th of a second.

And the outer measurement does not suffer from that...

Excellent ...

Ravinder Matte, July 03, 2007 - 11:26 am UTC

CPU time more than Elapsed Time. Why?

Tony, May 13, 2010 - 3:08 am UTC

Tom,

I have tkprof output for a query. I see CPU time more than the elapsed time. How is it possible?

More to Explore

Performance

Get all the information about database performance in the Database Performance guide.

Breadcrumb

Question and Answer

You Asked

and Tom said...

Rating

Comments

Write Consistency ?

CPU time Vs elapsed time

Write Consistency ?

could wait on the remote db

CPU time

Excellent ...

CPU time more than Elapsed Time. Why?

More to Explore

Performance

Big Difference between CPU and ELAPSED in TKPROF output

Breadcrumb

Question and Answer

You Asked

and Tom said...

Rating

Comments

Write Consistency ?

CPU time Vs elapsed time

Write Consistency ?

could wait on the remote db

CPU time

Excellent ...

CPU time more than Elapsed Time. Why?

More to Explore

Performance