Re: Tkprof result reading

From: Thomas Kyte <tkyte_at_us.oracle.com>
Date: 25 Jun 2001 18:58:08 -0700
Message-ID: <9h8q7g02cr6@drn.newsguy.com>

In article <bd9a9a76.0106251145.76ff5220_at_posting.google.com>, bchorng_at_yahoo.com says...
>
>I know "query" column in the tkprof output means buffer gets. But I don't know
>the difference between execute and fetch. Can someone please explain it ? And
>why would my elapsed time smaller than CPU time in this case ?
>
>Here is an example:
>
>call count cpu elapsed disk query current rows
>------- ------ -------- ---------- ---------- ---------- ---------- ----------
>Parse 1 0.02 0.00 0 0 0 0
>Execute 3003 0.88 0.70 3 30030 0 0
>Fetch 3003 0.13 0.20 2 3003 12012 3003
>------- ------ -------- ---------- ---------- ---------- ---------- ----------
>total 6007 1.03 0.90 5 33033 12012 3003
>
>Can someone explain the difference between execute (30030) and fetch (300)
>in this case and what exactly do they mean ?

well, technically speaking the different is we did 100 times the logical IO during the execute phase then we did during the fetch phase.

But, thats not very useful (obvious yes, useful no).

Given that we have

o no database version
o no query to look at
o no logic to analyze

the following is PURE conjecture on my part:

You are doing a select for update on a table (hence the execute phase shows logical IO). Most of the time, you do not find a record in this table when you do the select for update.

The execute phase of the query does some logical io to find that non-existent row most of the time -- work that the actual fetch does not have to perform.

Here is a contrived case to demonstrate with:

ops$tkyte_at_ORA8I.WORLD> -- create table t as select * from all_objects;
ops$tkyte_at_ORA8I.WORLD> 
ops$tkyte_at_ORA8I.WORLD> declare
  2      xxx number;
  3  begin
  4      for x in ( select rownum r, object_id from t where rownum <= 100 )
  5      loop
  6          if ( mod(x.r,100) <> 0 )
  7          then
  8              x.object_id := -x.object_id;
  9          end if;
 10  
 11          begin
 12              select object_id into xxx
 13                from t
 14               where object_id = x.object_id
 15                 for update;
 16          exception
 17              when others then null;
 18          end;
 19      end loop;

 20 end;
 21 /

PL/SQL procedure successfully completed.

Most of the time, I set the object_id to some value that will return 0 records by negating it. The tkprof for this shows:

SELECT OBJECT_ID
FROM
 T WHERE OBJECT_ID = :b1 FOR UPDATE

call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ----------

Parse        1      0.00       0.00          0          0          0           0
Execute    100      5.02       5.09          0      42000       1203           0
Fetch      100      0.05       0.05          0        420         12           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      201      5.07       5.14          0      42420       1215           1

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 44643 (recursive depth: 1)

Rows Row Source Operation

-------  ---------------------------------------------------
      1  FOR UPDATE

    103 TABLE ACCESS FULL T so, in my case, it means I was doing a select for update on an unindexed table -- the execute phase had to do it 100 times, the fetch phase once.

Are you doing something similar?

As for why the CPU was greater then the wall clock -- luck of the draw. You ran this on a machine where you were the only user (you had all of the resources). The granularity of the clock is only 1/100 of a second in tkprof so errors creep in. It was pure luck that the wall clock was less then cpu. Everything happened too fast to measure accurately.

>
>Thanks.
>
>-Bass Chorng

--
Thomas Kyte (tkyte@us.oracle.com)             http://asktom.oracle.com/ 
Expert one on one Oracle, programming techniques and solutions for Oracle.
http://www.amazon.com/exec/obidos/ASIN/1861004826/  
Opinions are mine and do not necessarily reflect those of Oracle Corp 

Received on Mon Jun 25 2001 - 20:58:08 CDT