statistics_level=ALL slows query 10x.
Date: Wed, 7 Mar 2012 17:59:31 +0000
Message-ID: <D0534F8D31056242BE8E38FA9413FDA817CB2317_at_M1EXCHMB13.mmi.local>
I have a database that when statistics_level=ALL is set, queries become 10x slower, spending all their time on CPU. I have run 10046 trace and verified that the plans are the same when I change this setting to TYPICAL. The reference query I have chosen is indicative of a set of batch queries that are all affected by this issue. I want to be able to use statistics_level=ALL periodically in production for performance diagnosis, this issue is making that impossible. The 10046 when statistics_level=TYPICAL shows lots of recursive sql. When statistics_level=ALL it show no recursive sql and all CPU time. Symptoms are the same when reference query is run serial or parallel. I have eyeballed the trace file and find no wait events emitted when the ALL query is on CPU.
What is the next thing to trace to find out where the time is being spent when statistics_level=ALL?
RH linux 64 update 4
11.2.0.2.4
Strace for 10 minutes shows this output. Again it looks like the CPU usage is not being emitted:
Process 28143 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
97.75 1.866363 349 5348 pread 1.72 0.032819 27 1207 readv 0.36 0.006791 0 20728 write
Tkprof for STATISTICS_LEVEL=TYPICAL
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4 0.02 0.02 3 5 0 0 Execute 4 0.08 4.61 0 0 0 0 Fetch 1 398.94 972.63 3546199 4425926 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 9 399.05 977.26 3546202 4425931 0 0
Misses in library cache during parse: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 6 0.00 0.00 SQL*Net message from client 6 0.00 0.00 rdbms ipc reply 3 2.00 4.52 db file sequential read 2205 0.03 5.82 asynch descriptor resize 1 0.00 0.00 Disk file operations I/O 37 0.00 0.02 db file scattered read 98675 0.06 611.66
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 83 0.00 0.01 0 0 0 0 Execute 1661 0.17 0.18 2 2 0 0 Fetch 2101 0.14 0.37 353 5714 0 3074
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3845 0.33 0.57 355 5716 0 3074
Misses in library cache during parse: 38 Misses in library cache during execute: 36
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ db file sequential read 333 0.01 0.22 asynch descriptor resize 1 0.00 0.00 Disk file operations I/O 7 0.00 0.00 db file scattered read 4 0.00 0.00
4 user SQL statements in session.
56 internal SQL statements in session.
60 SQL statements in session.
Trace file: DWPROD_ora_12351_GCStypical_10046.trc Trace file compatibility: 11.1.0.7
Sort options: default
1 session in tracefile.
4 user SQL statements in trace file.
56 internal SQL statements in trace file.
60 SQL statements in trace file.
42 unique SQL statements in trace file.
128292 lines in trace file.
977 elapsed seconds in trace file.
********************************************************************************
Tkprof for STATISTICS_LEVEL=ALL
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0 Execute 2 0.00 0.00 0 0 0 0 Fetch 1 4338.84 4819.95 2766175 4425926 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 4338.84 4819.95 2766175 4425926 0 0
Misses in library cache during parse: 0
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 4 0.00 0.00 SQL*Net message from client 4 0.00 0.00 asynch descriptor resize 1 0.00 0.00 Disk file operations I/O 36 0.00 0.02 db file scattered read 71464 0.11 511.30 db file sequential read 1870 0.03 5.52
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0 Execute 0 0.00 0.00 0 0 0 0 Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
Misses in library cache during parse: 0
2 user SQL statements in session.
0 internal SQL statements in session.
2 SQL statements in session.
Trace file: DWPROD_ora_6281_GCSALL_10046.trc Trace file compatibility: 11.1.0.7
Sort options: default
1 session in tracefile.
2 user SQL statements in trace file.
0 internal SQL statements in trace file.
2 SQL statements in trace file.
2 unique SQL statements in trace file.
81957 lines in trace file.
4819 elapsed seconds in trace file.
--
http://www.freelists.org/webpage/oracle-l
Received on Wed Mar 07 2012 - 11:59:31 CST