Performance of Autotrace

I have been having some performance problems when using autotrace in some production systems. I finally had time to check out why.

I enabled sql trace in my autotrace session to see what was causing the slow response. As you may already know setting autotrace on opens another session other than the session you are executing your query in. This second session reports statistics of the main session which executes your query. This second session is the one I have enabled sql trace for.

In the original session, I set the timing on to see the elapsed times and run a simple query which returns immediately.

SQL> set timing on
SQL> select sid from v$mystat where rownum=1;

SID
----------
20892

Elapsed: 00:00:00.00
SQL> select * from dual;

D
-
X

Elapsed: 00:00:00.00

Now I set autotrace on.

SQL> set autot trace

This opens another session for me. You can now query v$session and find out that you have 2 sessions, one with sid=20892 which is the main session and another one with a different sid. I enable sql trace for that other session to see what it is doing. From another session run the following to enable sql trace.

SQL> exec dbms_system.SET_SQL_TRACE_IN_SESSION(133,9526,true);

PL/SQL procedure successfully completed.

Now from the main session I execute the same simple query again and set autotrace off after that.

SQL> select * from dual;

Elapsed: 00:01:14.08

Execution Plan
----------------------------------------------------------
   0      SELECT STATEMENT Optimizer=CHOOSE
   1    0   TABLE ACCESS (FULL) OF 'DUAL'




Statistics
----------------------------------------------------------
          0  recursive calls
          0  db block gets
          3  consistent gets
          0  physical reads
          0  redo size
        205  bytes sent via SQL*Net to client
        273  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed

SQL> set autot off

Look at the elapsed time! It is more than 1 minutes with autotrace on. Now when I look at the trace file produced I see that the sql running this long is the following.

SELECT PT.VALUE
FROM
 SYS.V_$SESSTAT PT WHERE PT.SID=:1 AND PT.STATISTIC# IN (7,40,41,42,115,239,
  240,241,245,246) ORDER BY PT.STATISTIC#


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        4     73.41      73.03          0          0          0          20
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        8     73.41      73.03          0          0          0          20

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 32

Rows     Row Source Operation
-------  ---------------------------------------------------
     10  SORT ORDER BY
     10   FILTER
     10    FIXED TABLE FULL X$KSUSESTA
      1    FIXED TABLE FULL X$KSUSGIF

The view V_$SESSTAT is based on two fixed tables, named as X$KSUSESTA and X$KSUSGIF. X$KSUSESTA is a large object holding the statistics for all sessions. So, if you have thousands of sessions it may take a long time to query this fixed table and autotrace suffers from that. Here is the number of rows from this view in my instance.

SQL> select count(*) from X$KSUSESTA;

  COUNT(*)
----------
   7000000