Section 7.2. Oracle Kernel Timings

---

7.2 Oracle Kernel Timings

The Oracle kernel publishes only a few different types of timing information. Extended SQL trace output contains four important ones. You can see all four on the following two lines, generated by an Oracle release 9.0.1.2.0 kernel a Solaris 5.6 system:

 WAIT #34: nam='db file sequential read'  ela= 14118  p1=52 p2=2755 p3=1 FETCH #34:  c=0  ,  e=15656  ,p=1,cr=6,cu=0,mis=0,r=1,dep=3,og=4,  tim=1017039276349760  

The two adjacent lines of trace data shown here describe a single fetch database call. The timing statistics in these lines are the following:

ela= 14118

The Oracle kernel consumed an elapsed time of 14,118 microseconds (or m s, where 1 m s = 0.000 001 seconds) executing a system call denoted db file sequential read .

c=0

The Oracle kernel reports that a fetch database call consumed 0 m s of total CPU capacity.

e=15656

The kernel reports that the fetch consumed 15,656 m s of elapsed time.

tim=1017039276349760

The system time when the fetch concluded was 1,017,039,276,349,760 ( expressed in microseconds elapsed since midnight UTC 1 January 1970).

The total elapsed duration of the fetch includes both the call's total CPU capacity consumption and any time that the fetch has consumed during the execution of Oracle wait events. The statistics in my two lines of trace data are related through the approximation :

e c + ela

In this case, the approximation is pretty good on a human scale: 15656 0 + 14118, which is accurate to within 0.001538 seconds.

A single database call (such as a parse , execute , or fetch ) emits only one database call line (such as PARSE , EXEC , or FETCH ) to the trace data (notwithstanding the recursive database calls that a single database call can motivate). However, a single database call may emit several WAIT lines representing system calls for each cursor action line. For example, the following trace file excerpt shows 6,288 db file sequential read calls executed by a single fetch:

 WAIT #44: nam='db file sequential read' ela= 15147 p1=25 p2=24801 p3=1 ...   6,284 similar WAIT lines are omitted here for clarity   ... WAIT #44: nam='db file sequential read' ela= 105 p1=25 p2=149042 p3=1 WAIT #44: nam='db file sequential read' ela= 18831 p1=5 p2=115263 p3=1 WAIT #44: nam='db file sequential read' ela= 114 p1=58 p2=58789 p3=1 FETCH #44:c=7000000,e=23700217,p=6371,cr=148148,cu=0,mis=0,r=1,dep=1,og=4, tim=1017039304454213 

So the true relationship that binds the values of c , e , and ela for a given database call must refer to the sum of ela values that were produced within the context of a given database call:

This approximation is the basis for all response time measurement in the Oracle kernel.

---

Top