René Nyffenegger's collection of things on the web
René Nyffenegger on Oracle - Most wanted - Feedback
 

The meaning of count, cpu and elapsed in tkprof

Be sure to also take a look at Basics of tkprof.
In order to demonstrate the meaning of count, cpu and elapsed in tkprof, three different and simple SQL statements are executed. One of these SQL Statements is executed three times, one is executed twice and one is executed once. The only thing these statements actually do is call dbms_lock.sleep.
set feedback off

select spid from v,v where audsid= sys_context('userenv','sessionid') and addr=paddr;

alter session set sql_trace=true; 

begin /* three times */
  dbms_lock.sleep(1);
end;
/

begin /* once */
  dbms_lock.sleep(1);
end;
/

begin /* three times */
  dbms_lock.sleep(1);
end;
/

begin /* twice */ 
  dbms_lock.sleep(2);
end;
/

begin /* twice */ 
  dbms_lock.sleep(2);
end;
/

begin /* three times */
  dbms_lock.sleep(1);
end;
/

alter session set sql_trace=false;
If these statements are run and the trace file is tkprof'ed, it produces the following output:
begin /* three times */
  dbms_lock.sleep(1);
end;

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        3      0.01       0.01          0          0          0           0
Execute      3      0.00       3.10          0          0          0           3
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        6      0.01       3.11          0          0          0           3

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 206 

--------------------

begin /* twice */
  dbms_lock.sleep(2);
end;

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.01          0          0          0           0
Execute      2      0.00       4.09          0          0          0           2
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.00       4.10          0          0          0           2

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 206

--------------------


begin /* once */
  dbms_lock.sleep(1);
end;

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.01          0          0          0           0
Execute      1      0.00       1.03          0          0          0           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.01       1.04          0          0          0           1

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 206

The interesting parts are bold.