Skip to Main Content
  • Questions
  • Sql Execution Time v/s Elapsed time v/s CPU Time

Breadcrumb

Question and Answer

Connor McDonald

Thanks for the question, HIMANSHU.

Asked: May 12, 2016 - 11:14 am UTC

Last updated: June 13, 2018 - 1:58 am UTC

Version: 10 g

Viewed 10K+ times! This question is

You Asked

Hello ,

I have been working on Database monitoring stuff where we are looking for long running queries in DB . From the inbuilt setup which i have received from DBA , its showing CPU_TIME and ELAPSED_TIME but none of them is matching with Oracle Enterprise Manager under "Monitored SQL Executions" where i am looking at Duration column for any particular SQL ID .

Any of you could let me know whats the difference of Duration Column in OEM and Elapsed time .

And which one of column CPU_TIME and ELAPSED_TIME is good to use for monitoring long running queries .

Thanks ,
HS

and Chris said...

You'll need to speak with your DBA to find out the ELAPSED_TIME and CPU_TIME they've provided represent. It could be:

- Total time for all executions (this is what v$sql shows)
- Last execution time
- Average execution time
- Something else!

Elapsed_time is the total time the query takes*. This includes the CPU time + waits (I/O, network, etc.).

The elapsed time for a given execution should match the duration provided by SQL monitor. This is what you should pay most attention to.

If the queries run in parallel, this is:

"cumulative time for the query coordinator, plus all parallel query slave processes"

So this could be higher than the wall clock time for the query.

Rating

  (4 ratings)

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

Comments

Elapsed time confusion

BV, June 11, 2018 - 7:52 pm UTC

Hi Chris

There is definitely confusion between response time and elapsed time.

Say my query returns 200K records

Which is correct with regard to Elapsed time?

a) Does ET represent the time from the DB receiving the SQL to the second that it finds the first row?
b) Does ET represent the time from the DB receiving the SQL to the second that it returns the first row to the client?

Or

c) Does ET represent the time from the DB receiving the SQL to the second that it completes returning all 200K records to the client?

Please check any documentation of Oracle and there's no clear explanation of this.

I'll tell you an example. Please see here:

My spool file (for a query) shows this:

1076 rows selected.

Elapsed: 00:01:08.08


My TKPROF shows this (10046 tracing)

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.06       1.93         70         84          0           0
Fetch        3      0.83      47.72       1119       1143          0        1076
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      0.90      <b>49.66</b>       1189       1227          0        1076



So what is elapsed time here? Is it 49 seconds or 01:08 minutes?

Is that elapsed time of 49 seconds representing

a) finding of the block for the first row?
b) finding of the first row returned to the client?
c) returning of the first row returned to the client?
d) returning of the last row to the client (and the balance of 19 seconds between spool and tkprof is the network time to transfer the data)?

Thanks
BV
Connor McDonald
June 12, 2018 - 1:27 am UTC

It is "none of the above" :-) Well...sort of.

It depends on what the *client* is doing. Your (c) is the closest.

To explain what I mean, I did this in SQL Plus

SQL> create table t as select * from dba_objects;

Table created.


So that table has approx 100k rows. Then I popped into SQL Developer and did a simple "select * from t".

(My) SQL Developer will fetch 200 rows and then display to the user. So if I trace *just* that, I see this in the tkprof

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0         26           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.01       0.04          5          7          0         200
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.01       0.04          5          7         26         200


That elapsed time is the time it took to open, and fetch 200 rows. That query is still "open" (ie, I could fetch *more* rows from it).

If I keep scrolling down in SQL Dev to get more rows, I'll see stuff like this in the trace file when I re-process it

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        6      0.00       0.09         15         28          0        1200
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        8      0.00       0.09         15         28          0        1200

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 107  

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       6        0.00          0.00
  SQL*Net more data to client                     6        0.00          0.00
  SQL*Net message from client                     6       10.77         24.83
  Disk file operations I/O                        1        0.00          0.00
  db file scattered read                          2        0.01          0.01
********************************************************************************



So you can see the total elapsed time went up, but it does not contain the "dead time" (ie, when I was just looking at the screen) but the time to extract and fetch more rows. (You can see the 'dead time' in the SQL*Net message from client ... around 24 seconds)

So elapsed time is time spent doing work, where "work" is retrieving the data from the database *and* sending it to the requesting client.

Elapsed time

BV, June 12, 2018 - 1:25 pm UTC

Hi Chris

Thanks for your quick response. So as per your final statement, is it safe to say that ELAPSED TIME constitutes parsing time + DB waits + cpu time + DB time + SQL Data to client?

If so, why is my spool time (in SQL Plus) different from TKPROF's elapsed time?

Thanks,
Venkat
Connor McDonald
June 13, 2018 - 1:58 am UTC

tkprof is:

- fetch rows from buffer cache/datafiles
- present to client

sqlplus is:

- (implicitly the above) because it can't do anything without the data

PLUS

- format data to present in columns/paging/linesize etc
- render to screen
- write to file
- occasional file flushes

hence you'd expect it to be longer

Some things to improve the performance

- higher arraysize (to to say 500-1000)
- set termout off



Elapsed time

BV, June 12, 2018 - 3:52 pm UTC

Hi Connor

Sorry for mixing up your name with Chris'

Cheers
BV
Connor McDonald
June 13, 2018 - 1:55 am UTC

No probs :-)

Elapsed time

BV, June 13, 2018 - 4:06 pm UTC

Hi Connor

Thanks, it does start to make sense.

I'll do few more tests from different interfaces and go through them.

Many thanks
BV