What causes the difference between processor time and elapsed time in Oracle tkprof files

Question

When analyzing Oracle tkprof trace files, I noticed that sometimes there is a big difference between processor time and elapsed time, and I don’t know what causes it.

For instance:

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 

Waiting statistics look 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 am a software developer (not a database administrator), so I usually look at these trace files to find inefficient queries or see if I can use the index to stop a full table scan, etc. For this, I usually continue the processor time. In most cases, elapsed time is very similar to processor time.

I do not have access to the database that generated the trace file (from the client’s site), but I would like to understand what is happening so that I can make suggestions on how to reduce the elapsed time.

Answer 1

CPU time is the time when your request is really needed; the rest are waiting for resources. On a busy server, this may be largely due to the expectation of the processor that is currently being used by other users; it does not appear in wait statistics.

Answer 2

How busy is the system, what is the architecture, what does the request look like? How is the sga size?

The most amazing thing about this example is the parsing time. This poor server gets some things he doesn't like, which is not very fun ...

Typically, the elapsed time is the wall clock time it took to process a full request. CPU time, CPU usage time. For your system, I would try to find out why the parsing took so long. There is a good chance that if you decide this, you will also decide the sampling time. Ask for the addm report for the period in which the query was executed, and examine this. Oracle® Database 2 Day + 11g Performance Tuning Guide Release 2 (11.2) is a good place to get some insight into addm reports.

Answer 3

As Tony said, one of the common explanations for unaccounted tracing time is processor latency. The other one I experienced is the time taken to write to the trace file if something causes it to slow; but if so, you should see a big difference in hourly time when starting a request with or without trace.

The parsing time is huge. The analysis is usually associated with the CPU, while this does not show the processor time and a lot of elapsed time. The fact that you have significant latch free expectations may be a sign of a lot of parsing parses, but the time attributed to the wait is only about 1/10 of your elapsed parsing time.

So, I agree with Tony that fierce competition with the processor is a likely problem in this case. A large amount of parsing can contribute to this problem.