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

Times in tkprof output are not reliable, especially for very large numbers of very short operations, and particularly when recursive SQL due to PL/SQL packages
appears.

Apart from the problem of the coarse
granularity of the clock, tkprof also
manages to get confused when trying
to allow for recursive time inside procedures, and often ends up double-accounting.

You have to look at the trace file. You might also consider running with event
10046 level 8 on, so that you get trace lines showing where Oracle waited. This will produce a huge file, though, and slow things down quite dramatically.

--

Jonathan Lewis
Yet another Oracle-related web site: http://www.jlcomp.demon.co.uk

johnpaulcook_at_my-deja.com wrote in message <861vii$8lm$1_at_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 - 13:15:40 CST