What causes the difference between CPU time and El

Question

When analysing Oracle tkprof trace files I have noticed that there is sometimes a big difference between the cpu time and the elapsed time, and I don't know what causes it.

For example:

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00      42.09          0          0          0           0
Execute      1      0.01       0.01          0          0          0           0
Fetch       45     14.44      62.71      48664     505513          0        1871
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       47     14.45     104.82      48664     505513          0        1871

The wait statistics are like this:

 Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                      46        0.00          0.00
  SQL*Net message from client                    46        0.19          1.68
  buffer busy waits                             559        0.23          8.59
  db file scattered read                       5204        0.21          7.49
  db file sequential read                      4240        0.20         13.49
  latch free                                    215        0.11          3.62

I'm a software developer (not a DBA) so I'm generally looking these trace files to find inefficient queries or to see if an index could be used to stop a full table scan and so on. For this purpose I tend to go on the cpu time. In most cases the elapsed time is very similar to the cpu time.

I don't have access to the database that generated the trace file (it's from a client site) but I would like to understand what is going on so that I can make suggestions as to how to reduce the elapsed time.

Answer 1

The CPU time is the time your query actually needed; the rest is waiting for resources. On a busy server this could be largely due to waiting for CPU currently in use by other users; this doesn't show up in the wait stats.

Answer 2

How busy is the system, what is the architecture, how does the query look like? How is the sga sizing?

Most amazing in this sample is the parse time. That poor server gets some things thrown to it that does not look like a lot of fun ....

Normally, the elapsed time is the wall-clock time that it took to process the complete query. The cpu time, the time that the cpus were used. For your system I would go and try to find out why the parsing took so long. There is a good chance that it if you solve that, you also solve the fetch time. Ask for an addm report for the period in which the query ran and study that.Oracle® Database 2 Day + Performance Tuning Guide 11g Release 2 (11.2) is a good place to gain some understanding in addm reports.

Answer 3

As Tony said, one common explanation for unaccounted-for time in a trace is time spent waiting for the CPU. Another that I have experienced is time spent writing to the trace file itself, if something is causing that to occur slowly; but if this is the case you should see a big difference in clock time when running the query with or without trace.

The parse time is huge. Parsing is generally CPU-bound whereas this shows no CPU time and lots of elapsed time. The fact that you have significant latch free waits could be an indication of lots of parsing contention, but the time attributed to the wait is only about 1/10 of your elapsed parse time.

So I would agree with Tony that heavy CPU contention is a likely problem in this case. A large amount of parsing may be contributing to this problem.