strange tkprof output for PL/SQLs

From: Danisment Gazi Unal (Unal Bilisim) <dunal_at_unal-bilisim.com>
Date: Wed, 20 Mar 2002 11:01:13 -0800
Message-ID: <F001.0042ED42.20020320110113@fatcity.com>

Hello,

I did 2 tests for PL/SQL and SQL statements. This is the test for PL/SQL. I've enabled sql_trace from another session by DBMS_SYSTEM.SET_EV().

Here are my observations and questions:

• The caller PL/SQL package are seen at the end of the raw file as below:

PARSING IN CURSOR #1 len=19 dep=0 uid=5 oct=47 lid=5 tim=2882392980 hv=3659692972 ad='507cbd68'
BEGIN pdoug; END;
END OF STMT
EXEC
#1:c=0,e=0,p=3533,cr=5229,cu=132854,mis=1,r=1,dep=0,og=4,tim=2882392980 *** 2002-03-20 15:20:33.571

Here are the v$SQL results:

select SQL_TEXT,DISK_READS,BUFFER_GETS,ROWS_PROCESSED from v$sql where upper(SQL_TEXT) like '%DOUG%';

SQL_TEXT                                                   DISK_READS

BUFFER_GET ROWS_PROCE
---------------------------------------------------------- ----------
---------- ----------
INSERT INTO DOUG VALUES ( :b1,:b2 )
3533 138083 120000
BEGIN pdoug; END;
3533 138083 1

Comparision of PL/SQL package with the raw trace file:

Physical reads:

---

Raw trace file: 3533
V$SQL : 3533 Logical IO:

---

Raw trace file: 5229 + 132854 = 138083
V$SQL : 138083 As you see raw trace file and V$SQL are consistent for this parent PL/SQL statement. This is true for both
enabling sql_trace from current session or other session.

Here are the tkprof output for parent PL/SQL and its child SQL statement.

Child recursive statement called from parent PL/SQL statement:

INSERT INTO DOUG
VALUES
 ( :b1,:b2 )

call     count       cpu    elapsed       disk      query
current        rows

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

---

Parse        0      0.00       0.00          0          0
0           0
Execute  83646     41.52     110.37        218        565
92483       83646
Fetch        0      0.00       0.00          0          0
0           0

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

---

total    83646     41.52     110.37        218        565
92483       83646

Parent statement calls its recursive SQL statement given above:

BEGIN pdoug; END;

call     count       cpu    elapsed       disk      query
current        rows

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

---

Parse        0      0.00       0.00          0          0
0           0
Execute      1      0.00       0.00        844       1279
40206           1
Fetch        0      0.00       0.00          0          0
0           0

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

---

total        1      0.00       0.00        844       1279
40206           1

Here are the questions:

1- if recursive statements are included in the parent statement, why are the child statement's some
statistics(cpu,elapsed,current) greater than the parent statement's statistics. Also, please have a look at
parent statistics. is it possible for 1279+40206=41485 blocks to be processed in ZERO time and total elapsed time is ZERO too.

2- if recursive statements are not included in the parent statement, why tkprof output shows different
values for disk and logical IO. Here are the comparisions between tkprof output and V$SQL for parent PL/SQL:

Physical reads:

---

Raw trace file: 3533
tkprof output : 844

Logical IO:

---

Raw trace file: 5229 + 132854 = 138083
tkprof output : 1279 + 40206 = 41485

As a result, raw trace file is consistent with V$SQL for the parent statement. But tkprof reports different
values.

What is your comment ?

Thanks in advance...

--
Danisment Gazi Unal
http://www.unal-bilisim.com


-- 
Please see the official ORACLE-L FAQ: http://www.orafaq.com
-- 
Author: Danisment Gazi Unal (Unal Bilisim)
  INET: dunal_at_unal-bilisim.com

Fat City Network Services    -- (858) 538-5051  FAX: (858) 538-5051
San Diego, California        -- Public Internet access / Mailing Lists


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

To REMOVE yourself from this mailing list, send an E-Mail message
to: ListGuru_at_fatcity.com (note EXACT spelling of 'ListGuru') and in
the message BODY, include a line containing: UNSUB ORACLE-L
(or the name of mailing list you want to be removed from).  You may
also send the HELP command for other information (like subscribing).

Received on Wed Mar 20 2002 - 13:01:13 CST