Monday, May 21, 2007

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

4 comments:

  1. Yas what is your os and db versions, interesting post and thank you for sharing.

    Best regards.
    Tonguc

    ps: by the way, with this opportunity please let me invite you to OracleTURK; http://tech.groups.yahoo.com/group/oracleturk/join if you want to join your experiences are mostly welcomed.

    ReplyDelete
  2. Oh, I forgot to mention the version. This is 9.2.0.7 Enterprise Edition on Solaris 10.

    ReplyDelete
  3. This comment has been removed by a blog administrator.

    ReplyDelete
  4. This comment has been removed by a blog administrator.

    ReplyDelete