Re: TKPROF - SQL fast, PL/SQL slow?

From: <johnpaulcook_at_my-deja.com>
Date: Tue, 18 Jan 2000 15:07:11 GMT
Message-ID: <861vii$8lm$1@nnrp1.deja.com>

In article <85lgm8$k9o$1_at_nnrp1.deja.com>, michael_bialik_at_my-deja.com wrote:
> Is it possible to post the entire TKPROF result file?

It's about 90K. The original TKPROF exceeded the UDUMP limit and thus recorded only about 12% of all activity. The UDUMP file limit was increased to UNLIMITED and a new TRACE collected. TKPROF on the new file had accumulated elapsed times consistent with recorded wall clock time.

The original question remains - how does one determine how much time is spent executing PL/SQL, not SQL?

Here is a condensed version of the TKPROF. The many dozens of queries have been edited into two. Notice that the elapsed time of the queries is almost equal to the elapsed time of all recursive statements. Notice that the elapsed time of the package is almost equal to the elapsed time of all non-recursive statements. So is this reasoning valid:

It takes 189 seconds to execute the package. It takes 82 seconds to execute the SQL statements in the package. By subtraction, it appears that it takes 107 seconds to execute the PL/SQL. Is this correct?

BEGIN
TEST_OWNER.PKG_REPORT.SP_REPORT ( 2454 ); END; call count cpu elapsed disk query current rows ------- ----- ------ ------- ---- ----- ------- ----

Parse       1   0.02    0.02    0     0       0    0
Execute     1 147.90  189.31    0     6    2485    1
Fetch       0   0.00    0.00    0     0       0    0
------- ----- ------ ------- ---- ----- ------- ----
total       2 147.92  189.33    0     6    2485    1

Misses in library cache during parse: 1 Optimizer goal: CHOOSE
Parsing user id: 43 (TEST_OWNER)

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

Parse    24212  8.49   10.45    0      0       0     0
Execute  59011  8.62   10.95    8     56   23257  1330
Fetch    84869 16.62   20.00    0 379989   15138 22765

------- ------ ----- ------- ---- ------ ------- ----- total 168092 33.73 41.40 8 380044 38395 24095

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

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

Parse    24212  8.49   10.45    0      0       0     0
Execute  59011  8.62   10.95    8     56   23257  1330
Fetch    84869 16.62   20.00    0 379989   15138 22765

------- ------ ----- ------- ---- ------ ------- ----- total 168092 33.73 41.40 8 380044 38395 24095

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

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS call count cpu elapsed disk query current rows ------- ----- ------- ------- ---- ----- ------- ----

Parse       5    0.03    0.03    0     0       0    0
Execute     6  147.90  189.35    0     6    2485    3
Fetch       1    0.00    0.00    0     0       0    1
------- ----- ------- ------- ---- ----- ------- ----
total      12  147.93  189.38    0     6    2485    4

Misses in library cache during parse: 1

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS call count cpu elapsed disk query current rows ------- ----- ----- ------- ---- ------ ------- -----

Parse   24212 16.98   20.51    0      0       0     0
Execute 59011 17.24   22.41   16    111   46513  2660
Fetch   84869 33.24   39.91    0 759867   30276 45530

------- ----- ----- ------- ---- ------ ------- ----- total 68092 67.46 82.83 16 759978 76789 48190

Misses in library cache during parse: 1

24169 user SQL statements in session.

49 internal SQL statements in session. 24218 SQL statements in session.

Sent via Deja.com http://www.deja.com/
Before you buy. Received on Tue Jan 18 2000 - 09:07:11 CST