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

In your particular example, the biggest problem is the very large number of very short operations. For example you record 80,000 fetches in an elapsed time of 12,000 hundredths of a second. i.e. 6.5 fetches every hundredth of a second.

Since Oracle measures these times to the hundredth, you probably have very large numbers of calls that used less than 1/100 of a second, but have to record at zero. elapsed.

One thing you could do, if you can be bothered, is to scan through the trace file listing out the 'tim=xxxxxxxx' columns and then processing them to find any large jumps. This may give you a clue about where the excess time has gone.

--

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

johnpaulcook_at_my-deja.com wrote in message <85i2js$qs$1_at_nnrp1.deja.com>...
>The TKPROF totals of nonrecursive and recursive SQL statements don't
>sum to a number about 12% of the actual elapsed time for executing the
>package. Where is the rest of the time spent? PL/SQL statements?
>There is an enormous amount of processing done in PL/SQL. If the
>majority of the time is indeed spent executing PL/SQL, then recoding in
>C might be something to consider.
>
>************************************************************************
>
>OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
>
>call count cpu elapsed disk query current rows
>------- ----- ---- ------- ---- ----- ------- ----
>Parse 3 0.07 0.07 0 0 0 0
>Execute 3 0.02 0.02 0 0 0 1
>Fetch 1 0.01 0.01 0 0 0 1
>------- ----- ---- ------- ---- ----- ------- ----
>total 7 0.10 0.10 0 0 0 2
>
>Misses in library cache during parse: 3
>Misses in library cache during execute: 1
>
>
>OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
>
>call count cpu elapsed disk query current rows
>------- ------ ------ ------- ---- ------ ------- -----
>Parse 24747 14.39 14.37 0 0 0 0
>Execute 59190 18.77 54.16 324 103 74483 3964
>Fetch 80250 117.06 119.60 1373 482813 37239 39450
>------- ------ ------ ------- ---- ------ ------- -----
>total 164187 150.22 188.13 1697 482916 111722 43414
>
>Misses in library cache during parse: 0
>Misses in library cache during execute: 1
>
>24715 user SQL statements in session.
> 36 internal SQL statements in session.
>24751 SQL statements in session.
> 49 statements EXPLAINed in this session.
>************************************************************************
>Trace file: ././test_ora_12469.trc
>Trace file compatibility: 7.03.02
>Sort options: default
>
> 1 session in tracefile.
> 24715 user SQL statements in trace file.
> 36 internal SQL statements in trace file.
> 24751 SQL statements in trace file.
> 63 unique SQL statements in trace file.
> 49 SQL statements EXPLAINed using schema:
> TEST_OWNER.prof$plan_table
> Default table was used.
> Table was created.
> Table was dropped.
> 487079 lines in trace file.
>
>The actual execution time for the entire package is 1506 seconds.
>Notice that nonrecursive statements total 0.10 second of elapsed time
>and recursive statements total 188.13 seconds of elapsed time. Where
>is the rest of the time spent?
>
>UTLBSTAT was executed, then the same package was executed on a dataset
>1/4th of the size of the TKPROF dataset, then UTLESTAT was executed
>(there was other activity on the system):
>
>Event Name Count Total Time Avg Time
>----------------------------- ----- ---------- --------
>rdbms ipc message 363 544863 1501
>queue messages 183 182226 995.77
>SQL*Net message from client 130 117452 903.48
>db file sequential read 89 196 2.2
>write complete waits 62 90 1.45
>log file switch completion 2 39 19.5
>log file sync 6 10 1.67
>control file sequential read 14 6 .43
>refresh controlfile command 4 4 1
>file open 36 1 .03
>SQL*Net message to client 130 0 0
>SQL*Net more data from client 82 0 0
>SQL*Net more data to client 20 0 0
>13 rows selected.
>SVRMGR>
>SVRMGR>
>SVRMGR> Rem System wide wait events for background processes (PMON,
>SMON, etc)
>SVRMGR> select n1.event "Event Name",
> 2> n1.event_count "Count",
> 3> n1.time_waited "Total Time",
> 4> round(n1.time_waited/n1.event_count, 2) "Avg Time"
> 5> from stats$bck_event n1
> 6> where n1.event_count > 0
> 7> order by n1.time_waited desc;
>Event Name Count Total Time Avg Time
>---------------------------- ----- ---------- --------
>rdbms ipc message 16329 711922 43.6
>smon timer 7 210007 30001
>pmon timer 604 181804 301
>log file parallel write 15169 13058 .86
>db file parallel write 133 737 5.54
>control file parallel write 638 203 .32
>direct path read 60 53 .88
>control file sequential read 88 25 .28
>log file single write 8 11 1.38
>db file sequential read 1 5 5
>log file sequential read 4 5 1.25
>log file sync 3 5 1.67
>direct path write 60 1 .02
>file identify 8 0 0
>file open 8 0 0
>15 rows selected.
>
>All Hit ratios are 1. Zero reloads. Zero Get Miss. Zero sleeps.
>Where is all of the time being used up?
>
>I was told that rdbms ipc message, queue messages, SQL*Net message from
>client all indicate that the time was spent communicating with the
>client via SQL*Net. Is this true?
>
>Is there a tool for profiling assignments and flow control inside
>PL/SQL code since TKPROF only profiles SQL statements?
>
>
>Sent via Deja.com http://www.deja.com/
>Before you buy.
Received on Wed Jan 12 2000 - 13:32:12 CST