Hi, We are using version 11.2.0.4 or oracle Exadata. We have one process which which is showing variable performance , sometimes it finishes in ~1.5hr and sometime it runs for ~5hr. As this process executes thousands of small sql's(finishing in subseconds) which is having different sqlids due to usage of different literals, so we have turned on the 10046 trace to see the cause of the slowness, if its really due to few of those quick sql's opting for bad execution path or its some latency at client side. We have turned on the trace for ~30minutes during slow execution and during fast execution, as because the file size was increasing very fast.
Now i have the tkprof which is ~220k +lines, and i tried to read it from first line to see if i will see difference in path of execution for any specific sqls between the slow and the fast execution, and i checked few hundred but i didnt find any. I do see from the summary section of the TKPROF that the fast execution is showing more number of sqls(both recursive and non recursive) executed during those ~30minutes as compared to the Slow execution. So does this mean that there must be few sqls which are opting for bad execution path causing higher execution time? I have published the summary section of bothe fast and slow execution below , want to understand from experts if anything obvious from the summary section of the TKPROF which gives us pointer for debugging the issue?
********TKPROF for Fast execution*************
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 10484 28.54 31.28 0 82322 0 0
Execute 5242 0.34 0.35 0 224 0 0
Fetch 5244 821.35 830.05 56 331818913 0 11329
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 20970 850.23 861.69 56 331901459 0 11329
Misses in library cache during parse: 6694
Misses in library cache during execute: 11
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 26725 0.00 0.01
SQL*Net message from client 26724 0.21 27.05
library cache lock 361 0.00 0.05
library cache pin 326 0.00 0.03
cell single block physical read 56 0.01 0.05
SQL*Net more data to client 10 0.00 0.00
gc current block 2-way 4 0.00 0.00
latch: shared pool 5 0.00 0.00
latch: cache buffers chains 3 0.00 0.00
latch free 1 0.00 0.00
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 25437 1.17 1.18 0 0 0 0
Execute 25437 12.50 12.74 0 0 0 0
Fetch 25437 72.74 73.82 0 2200816 0 25437
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 76311 86.42 87.75 0 2200816 0 25437
Misses in library cache during parse: 41
Misses in library cache during execute: 41
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
library cache lock 8 0.00 0.00
library cache pin 7 0.00 0.00
7089 user SQL statements in session.
0 internal SQL statements in session.
7089 SQL statements in session.
********************************************************************************
Trace file: /tmp/YYYYYY.trc
Trace file compatibility: 11.1.0.7
Sort options: default
1 session in tracefile.
7089 user SQL statements in trace file.
0 internal SQL statements in trace file.
7089 SQL statements in trace file.
6653 unique SQL statements in trace file.
2324669 lines in trace file.
979 elapsed seconds in trace file.
********TKPROF for Slow execution*************
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 9252 47.70 63.11 41784 73472 0 0
Execute 4626 0.47 0.46 72 140 0 0
Fetch 4625 927.34 950.39 16736 370353377 0 7266
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 18503 975.52 1013.97 58592 370426989 0 7266
Misses in library cache during parse: 5850
Misses in library cache during execute: 9
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 23806 0.00 0.02
SQL*Net message from client 23806 0.20 23.32
cell single block physical read 58577 0.13 23.91
latch: shared pool 44 0.00 0.00
library cache pin 203 0.00 0.03
library cache lock 204 0.00 0.03
gc current block 3-way 8 0.00 0.00
gc cr grant 2-way 51 0.00 0.00
row cache lock 4 0.00 0.00
gc current block 2-way 13 0.00 0.00
latch: row cache objects 7 0.00 0.00
latch: cache buffers chains 55 0.00 0.00
library cache: mutex X 26 0.01 0.01
latch: ges resource hash list 1 0.00 0.00
latch free 1 0.00 0.00
latch: object queue header operation 2 0.00 0.00
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 22830 2.06 2.08 0 0 0 0
Execute 22855 16.72 17.37 0 0 0 0
Fetch 22936 90.64 93.96 11 2164238 0 22939
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 68621 109.43 113.42 11 2164238 0 22939
Misses in library cache during parse: 60
Misses in library cache during execute: 60
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
cell single block physical read 71 0.00 0.02
gc current block 3-way 3 0.00 0.00
gc cr grant 2-way 7 0.00 0.00
row cache lock 5 0.00 0.00
gc current block 2-way 7 0.00 0.00
latch: cache buffers chains 1 0.00 0.00
gc cr block 3-way 1 0.00 0.00
6293 user SQL statements in session.
20 internal SQL statements in session.
6313 SQL statements in session.
********************************************************************************
Trace file: xxxxxx.trc
Trace file compatibility: 11.1.0.7
Sort options: prsela exeela fchela
1 session in tracefile.
6293 user SQL statements in trace file.
20 internal SQL statements in trace file.
6313 SQL statements in trace file.
5794 unique SQL statements in trace file.
2189590 lines in trace file.
1154 elapsed seconds in trace file.