 Interpreting tkprof [message #162643] |
Sun, 12 March 2006 15:31  |
sophieharris
Messages: 3
Registered: March 2006
Location: UK
|
Junior Member |
|
|
Hi all,
I've got a problem with a poorly performing database v9.2. I traced one of the sessions and the statements look harmless enough, but they are executed thousands of times. For example this statement racked up most elapsed time in the trace:
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 16334 1.51 1.84 0 0 0 0
Fetch 32231 80.48 141.48 6505 10713714 0 17162
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 48566 82.00 143.32 6505 10713714 0 17162
I've checked the statement and it's using an index, and it works fine when I execute it once. In this session it was executed over 16,000 times which I guess is why the query count looks so alarming.
The summary of all the statements in the session is copied below.
Can anybody give me some pointers as to where to start tuning as I'm at a bit of a loss. Should I perhaps go back to the vendor to query why statements are being executed thousands of times? Perhaps one big fetch might be better than thousands....?
The elapsed tot for non-recursive statements is 374, and for recursive statements is 455. Is there something I should be worried about there?
I appreciate any help you can offer.
Thanks,
Sophie
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 13 0.65 0.96 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 12133 141.25 373.05 33093 1314753 5 48529
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 12147 141.90 374.01 33093 1314753 5 48529
Misses in library cache during parse: 11
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 191 0.04 0.02 0 0 0 0
Execute 193681 25.64 27.48 0 0 0 0
Fetch 223686 109.18 427.97 35767 11335501 0 127817
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 417558 134.87 455.48 35767 11335501 0 127817
|
|
|
|
| Re: Interpreting tkprof [message #162682 is a reply to message #162643] |
Mon, 13 March 2006 00:52  |
rleishman
Messages: 3728
Registered: October 2005
Location: Melbourne, Australia
|
Senior Member |
|
|
For a statement to rack up 16000+ executions in a single session, it has to be inside a loop - probably there is a cursor and you are executing this SQL for each row returned.
You need to get rid of SQLs inside a loop. Can the SQL be merged into the cursor so that all of the values you need are returned in the cursor?
_____________
Ross Leishman
|
|
|
|
| Re: Interpreting tkprof [message #163048 is a reply to message #162682] |
Tue, 14 March 2006 15:14 |
sophieharris
Messages: 3
Registered: March 2006
Location: UK
|
Junior Member |
|
|
Thank you Ross for your comments. The application code is unknown to me, it's provided by a vendor. Their take on the performance problems is that it's our problem and we need to buy more hardware. I'm trying to determine if the problem is with the application.
So one thing I could take back to them is that they may be executing N times, when they could actually do one big fetch. (if they change their logic)
Is there anything else about these tkprof results that jumps out?
Kinf Regards,
Sophie
|
|
|
|
| Re: Interpreting tkprof [message #163087 is a reply to message #163048] |
Tue, 14 March 2006 21:45 |
rleishman
Messages: 3728
Registered: October 2005
Location: Melbourne, Australia
|
Senior Member |
|
|
Given that the SQL is nested, it is performing OK at 200-300 rows/sec. However, if you didn't have to execute for every row, you could expect performance of several thousand per second. You can test this yourself with a simple join Vs. nested cursor over 100,000 rows.
Based on these facts:
- There is only 1 non-recursive execute, with 12133 fetches (indicates a cursor - not a procedure call)
- The CPU and ELAPSED for RECURSIVE is similar but slightly less than the NON-RECURSIVE total (indicates that the recursive SQL is actually code within PL/SQL, not Oracle querying the data-dictionary)
This indicates to me that the execution of a single cursor (and the resultant fetches) caused a PL/SQL function to be run many thousands of times, which in turn performed its own SELECT statements.
This could be a cursor of the form:SELECT ..., my_pack.my_func(a.val)
FROM big_table a
If I'm right, this is not a terribly smart way to code a cursor. It is really no different to the loop functionality I described earlier, except the cursor is probably embedded in non-PL/SQL application code rather than in a PL/SQL proc/func.
Unless you can get the application code re-written, there is very little you can do. If this code is supposed to handle high volumes, then it should have been written without nesting (ie. no SQLs in loops, no SQLs in user-defined functions, no joins or sub-queries optimized for Nested-Loops joins).
If you are REALLY desperate, you might be able to get a SMALL improvement (say 20%) by hash clustering the table that is the subject of the query executed 16334 times. This is a pretty drastic measure though, and could have significant adverse effect on other queries. Make sure you fully understand Hash Clusters before you try this.
_____________
Ross Leishman
|
|
|
|
 Re: Interpreting tkprof [message #163457 is a reply to message #163087] |
Thu, 16 March 2006 15:42 |
sophieharris
Messages: 3
Registered: March 2006
Location: UK
|
Junior Member |
|
|
Hi Ross,
Thanks again for your response. I'm going to write up a report for the vendor and I'll make enquiries about the loops/nesting.
Much appreciated,
Sophie
|
|
|
|
] 
Blog
Search
Help
Members
Register
Login
Home
