Hello,
Database version: 11.2.0.3
I'm trying to tune some highly procedural legacy code ( like I've never seen before ), indentifying bottlenecks with the help of trace/tkprof.
I have difficulty in understanding what causes the high value for SQL*Net message for client here.
(nice explanation of that wait event: http://asktom.oracle.com/pls/apex/f?p=100:11:0::::P11_QUESTION_ID:1860804200346441327 ).
This is the output for the main procedure (had to change all object names for obvious reasons):
begin
package.procedure( parameter1, parameter2 );
end;
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 3331.38 3352.43 4 9 12 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 3331.39 3352.43 4 9 12 0
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 60
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 39748 0.00 0.23
log file switch completion 3 0.01 0.01
log buffer space 5 2.34 4.09
log file switch (checkpoint incomplete) 2 0.29 0.29
SQL*Net break/reset to client 2 0.01 0.01
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 7150.16 7150.16
********************************************************************************
My first question is: Can the high value SQL*Net message for client be caused by excessive parsing?
Because I see tons of queries like below in the tkprof, where the number of parses is always (and/or almost) equal to the number of executes:
SELECT *
FROM
TABLE WHERE COLUMN = :b1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 38062 0.51 0.51 0 0 0 0
Execute 38129 1.40 1.38 0 0 0 0
Fetch 38129 0.17 0.21 1 38129 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 114320 2.09 2.10 1 38129 0 0
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 60 (recursive depth: 1)
Number of plan statistics captured: 38062
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
0 0 0 TABLE ACCESS BY INDEX ROWID TABLE (cr=1 pr=0 pw=0 time=5 us cost=1 size=20 card=1)
0 0 0 INDEX UNIQUE SCAN INDEX (cr=1 pr=0 pw=0 time=4 us cost=1 size=0 card=1)(object id 78217)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file sequential read 1 0.00 0.00
********************************************************************************
So, my second question is:
What is causing the overall excessive parsing here, since all the queries are using bind variables?
(I could not find any dynamic sql, by the way)
Where should I start looking, does anyone recognize this perhaps?
Any pointers are welcome!