statistics_level=ALL slows query 10x.

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


Other related posts: