SQL tracing

Displaying the execution plan
Obtaining trace files

This page gives examples of how to analyse a particular SQL process in order to gain a better understanding of how Oracle is executing the process and, hopefully, identifying where any particular performance bottlenecks are occurring.

Displaying the execution plan

AUTOTRACE

AUTOTRACE is a SQL*Plus feature which automates the production of explain plans, which has been available since Oracle 7.3. It relies on you having created a role (as SYS) called PLUSTRACE. The creation of this role is done by executing the %ORACLE_HOME%/sqlplus/admin/plustrce.sql script. This role is then GRANTed to the user who wants to do the EXPLAIN PLAN. It also relies on the existence of a table called PLAN_TABLE. This table is typically created by running the %ORACLE_HOME%/rdbms/admin/utlxplan.sql script. Typically, this is created as SYS and then a public synonym is created for it, but it can just be created in the necessary schema, if so required.

Here's an example output.

SQL> SET AUTOTRACE ON
SQL> SELECT SYSDATE FROM DUAL;

SYSDATE
---------
22-SEP-03

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
        387  bytes sent via SQL*Net to client
        503  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed

This is the full output, and also runs the query.

Note, you can generate the plan and the statistics but without viewing the output of the query by specifying SET AUTOTRACE TRACEONLY. You can further filter by specifying the SET AUTOTRACE TRACEONLY STATISTICS or SET AUTOTRACE TRACEONLY EXPLAIN. Also, specifying any type of AUTOTRACE which generates statistics has to run the query, SET AUTOTRACE TRACEONLY EXPLAIN generates the plan but without running the query.

An interesting piece of information about AUTOTRACE is that setting it on with any option which gathers statistics actually generates another session, running as the current user, which is used to gather statistics about the main session, i.e.

SQL> select count(*) from v$session;

  COUNT(*)
----------
        15

1 row selected.

SQL> set autotrace on
SQL> select count(*) from v$session; 

  COUNT(*)
----------
        16

1 row selected.

The only option which does not generate this extra session is SET AUTOTRACE TRACEONLY EXPLAIN, since this does not gather statistics.

This "extra" session can sometimes pose it's own SQL performance challenges, an example of the diagnosis of which (amounting to tracing the "extra" session) can be found at http://oracletoday.blogspot.com/2007/05/performance-of-autotrace_21.html.

Of course, to turn AUTOTRACE off, use

SQL> SET AUTOTRACE OFF

For more information, see http://download-uk.oracle.com/docs/cd/B19306_01/server.102/b14357/ch12040.htm#SQPUG066.

DBMS_XPLAN

DBMS_XPLAN is a mechanism for generating the explain plans, and also allows programmatic access to the output. It is available from Oracle 9.2 and above, although, as per usual, it gets extended every release. Here, I'll go into some of the more common usages.

Whereas AUTOTRACE relies on the existence of the PLUSTRACE role, DBMS_XPLAN does not, and just relies on the existence of PLAN_TABLE (plus necessary GRANTs etc.), although you can change the name of the table now (via the table_name parameter of DBMS_XPLAN.DISPLAY, and the INTO clause of EXPLAIN PLAN).

DISPLAY

DBMS_XPLAN.DISPLAY is one of the best ways of reporting against plan_table that you can use, since it gives information, not only of the plan itself, but also the actual steps in the plan which Oracle has applied the predicate(s) against.

You use the following general syntax to populate plan_table with the execution path of query :

EXPLAIN PLAN
[SET STATEMENT_ID = 'statement_id']
[INTO table_name]
FOR
  query;

Once this is done, you then query the output of the DBMS_XPLAN.DISPLAY function (passing in the statement_id if you specified one), i.e. :

SQL> EXPLAIN PLAN FOR
  2  SELECT * FROM DUAL;

Explained.

SQL> SELECT * FROM TABLE( dbms_xplan.display );

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------

--------------------------------------------------------------------
| Id  | Operation            |  Name       | Rows  | Bytes | Cost  |
--------------------------------------------------------------------
|   0 | SELECT STATEMENT     |             |       |       |       |
|   1 |  TABLE ACCESS FULL   | DUAL        |       |       |       |
--------------------------------------------------------------------

Note: rule based optimization

9 rows selected.

Also, the output is not fixed, it only shows relevant information, if we had a table which required temp space, for example, it'd show that as well for each step, i.e.

SQL> CREATE TABLE t AS SELECT object_name FROM dba_objects;

Table created.

SQL> ANALYZE TABLE t COMPUTE STATISTICS;

Table analyzed.

SQL> EXPLAIN PLAN FOR
  2  SELECT object_name, count(*)
  3  FROM   t
  4  GROUP BY object_name;

Explained.

SQL> SELECT * FROM TABLE( dbms_xplan.display );

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------

----------------------------------------------------------------------------
| Id  | Operation            |  Name       | Rows  | Bytes |TempSpc| Cost  |
----------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |             | 24239 |   520K|       |   192 |
|   1 |  SORT GROUP BY       |             | 24239 |   520K|  1736K|   192 |
|   2 |   TABLE ACCESS FULL  | T           | 38361 |   824K|       |    16 |
----------------------------------------------------------------------------

Note: cpu costing is off

10 rows selected.

The new EXPLAIN PLAN allows you to even see predicate information, and even how Oracle will manipulate the predicate terms. This particular feature is handy for seeing information such as "Why isn't my index being used?" etc.

SQL> CREATE TABLE t
  2  ( a VARCHAR2(10) );

Table created.

SQL> INSERT INTO t VALUES ('1');

1 row created.

SQL> EXPLAIN PLAN FOR
  2  SELECT *
  3  FROM   t
  4  WHERE  a = 1;

Explained.

SQL> SELECT * FROM TABLE(dbms_xplan.display);

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------

--------------------------------------------------------------------
| Id  | Operation            |  Name       | Rows  | Bytes | Cost  |
--------------------------------------------------------------------
|   0 | SELECT STATEMENT     |             |       |       |       |
|*  1 |  TABLE ACCESS FULL   | T           |       |       |       |
--------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------


PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
   1 - filter(TO_NUMBER("T"."A")=1)

Note: rule based optimization

14 rows selected.

It is easy to see here, therefore, that in order to fulfil our predicate of "a=1", the "a" is converted to a number, via TO_NUMBER first. This also explains why Oracle will fail if there are non-numbers in the set, i.e.

SQL> INSERT INTO t VALUES ('X');

1 row created.

SQL> SELECT *
  2  FROM   t
  3  WHERE  a = 1;
ERROR:
ORA-01722: invalid number

We should, therefore, aim to compare like with like, i.e. ensure datatypes are consistent. If predicates are involved, any conversion functions located within the filter(..) operation, need to be looked at, since it's just extra work, i.e. to "fix" the above example :

SQL> EXPLAIN PLAN FOR
  2  SELECT *
  3  FROM   T
  4  WHERE  A = '1';

Explained.

SQL> SELECT * FROM TABLE(dbms_xplan.display);

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------

--------------------------------------------------------------------
| Id  | Operation            |  Name       | Rows  | Bytes | Cost  |
--------------------------------------------------------------------
|   0 | SELECT STATEMENT     |             |       |       |       |
|*  1 |  TABLE ACCESS FULL   | T           |       |       |       |
--------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------


PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
   1 - filter("T"."A"='1')

Note: rule based optimization

14 rows selected.

i.e. converting the a=1 in the predicate to a='1', then the TO_NUMBER is removed.

DISPLAY_CURSOR

As of 10g, Oracle added quite a few new functions to DBMS_XPLAN. One of the best is DISPLAY_CURSOR. It allows you a much greater detail of information for a given cursor, either the last one executed, or any in the v$sql_plan view by specified the SQL_ID of the relevant statement, such as the actual as well as estimated cardinalities for the relevant steps in the plan, eliminating the need to manually query v$sql, v$sql_plan, v$sql_plan_statistics, v$sql_plan_statistics_all etc.

There are a few things to consider, though. The full stats of the query will ONLY be given if the /*+ gather_plan_statistics */ hint is used, or setting statistics_level=ALL at session or system level. For a great article on STATISTICS_LEVEL, see here.

FUNCTION DISPLAY_CURSOR RETURNS DBMS_XPLAN_TYPE_TABLE
 Argument Name                  Type                    In/Out Default?
 ------------------------------ ----------------------- ------ --------
 SQL_ID                         VARCHAR2                IN     DEFAULT
 CURSOR_CHILD_NO                NUMBER(38)              IN     DEFAULT
 FORMAT                         VARCHAR2                IN     DEFAULT

Here's sample output for the last SQL statement executed, which is acheived by specifying NULL for the sql_id and cursor_child_no parameters.

SQL> SELECT /*+ gather_plan_statistics */ 'x'
  2    FROM dual
  3   WHERE dummy = 'X';

'
-
x

SQL> SELECT * FROM TABLE(dbms_xplan.display_cursor(null, null, 'ALLSTATS LAST'));

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------

SQL_ID  c51xuz980jfcq, child number 0
-------------------------------------
SELECT /*+ gather_plan_statistics */ 'x'   FROM dual  WHERE dummy = 'X'

Plan hash value: 272002086

------------------------------------------------------------------------------------

| Id  | Operation         | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------
|*  1 |  TABLE ACCESS FULL| DUAL |      1 |      1 |      1 |00:00:00.01 | 3 |
------------------------------------------------------------------------------------

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter("DUMMY"='X')

17 rows selected.

See the extra "E-Rows" and "A-Rows" columns? As you can probably infer, "E-Rows" is the number of estimated rows that Oracle expects that step in the plan to return, whereas "A-Rows" is the actual number.

As many people who know me will know, I very much extol the virtues of the "Card" / "Rows" column in standard EXPLAIN PLAN output. Ensuring that Oracle gets a good estimation of the number of rows that a given step will process is crucial to obtaining an efficient plan. This extra information now gives us an excellent tool for tuning the SQL.

Note, however, it is important to realise what the "Starts" column means, and also how it can mean that the "A-Rows" and "E-Rows" columns can be radically different, but without there being a significant problem. The "Starts" column is the number of times that that step in the plan is "executed", and, unfortunately, the "A-Rows" column is the cumulative count over all executions, whereas the "E-Rows" is the estimate for each execution of the step.

Now, let's try getting a random SQL statement from v$sql and getting it's information. We do this by supplying the "sql_id" and "child_number" from v$sql into the parameters instead of NULL for the last executed by the current session :

SQL> select sql_id, child_number
  2  from v$sql
  3  where rownum = 1;

SQL_ID        CHILD_NUMBER
------------- ------------
1fkh93md0802n            0

SQL> SELECT *
  2  FROM TABLE(dbms_xplan.display_cursor('1fkh93md0802n', '0', 'ALLSTATS LAST'));

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------

SQL_ID  1fkh93md0802n, child number 0
-------------------------------------
select   LOW_OPTIMAL_SIZE,           HIGH_OPTIMAL_SIZE,
OPTIMAL_EXECUTIONS,           ONEPASS_EXECUTIONS,
MULTIPASSES_EXECUTIONS,           TOTAL_EXECUTIONS    from
GV$SQL_WORKAREA_HISTOGRAM    where  INST_ID = USERENV('Instance')

Plan hash value: 2485227045

---------------------------------------
| Id  | Operation        | Name       |

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------

---------------------------------------
|*  1 |  FIXED TABLE FULL| X$QESMMIWH |
---------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - filter("INST_ID"=USERENV('INSTANCE'))

Note
-----

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------

   - rule based optimizer used (consider using cbo)
   - Warning: basic plan statistics not available. These are only collected when :
       * hint 'gather_plan_statistics' is used for the statement or
       * parameter 'statistics_level' is set to 'ALL', at session or system level

27 rows selected.

Note, we get the warning at the end because the statement is a) A system query using the RBO (i.e. x$qesmmiwh does not have stats), and b) the gather_plan_statistics hint was not specified.

But, this should go to show just how amazingly useful and easy it is to get the actual plan for a SQL statement which is in v$sql.

For more information on EXPLAIN PLAN, see http://download-uk.oracle.com/docs/cd/B19306_01/server.102/b14200/statements_9010.htm#SQLRF01601.

UTLXPLS.SQL

Prior to 9.2, you utilised a script, %ORACLE_HOME%/rbdms/admin/utlxpls.sql, which queried the PLAN_TABLE.

The basic mechanism is the same as in DBMS_XPLAN, except that instead of querying the DBMS_XPLAN.DISPLAY function, you ran the utlxpls.sql script, which is some quite complex SQL (utilising CONNECT BYs etc) for formatting the output.

This is an example of the query (at 9.0.1) that is in utlxpls.sql :


select '| Operation                 |  Name              |  Rows | Bytes|  Cost  | Pstart| Pstop |'  as "Plan Table" from dual
union all
select '------------------------------------------------------------------------------------------' from dual
union all
select * from
(select /*+ no_merge */
       rpad('| '||substr(lpad(' ',1*(level-1))||operation||
            decode(options, null,'',' '||options), 1, 27), 28, ' ')||'|'||
       rpad(substr(decode(substr(object_name, 1, 7), 'SYS_LE_', null, object_name)
                   ||' ',1, 19), 20, ' ')||'|'||
       lpad(decode(cardinality,null,'  ',
                decode(sign(cardinality-1000), -1, cardinality||' ',
                decode(sign(cardinality-1000000), -1, trunc(cardinality/1000)||'K',
                decode(sign(cardinality-1000000000), -1, trunc(cardinality/1000000)||'M',
                       trunc(cardinality/1000000000)||'G')))), 7, ' ') || '|' ||
       lpad(decode(bytes,null,' ',
                decode(sign(bytes-1024), -1, bytes||' ',
                decode(sign(bytes-1048576), -1, trunc(bytes/1024)||'K',
                decode(sign(bytes-1073741824), -1, trunc(bytes/1048576)||'M',
                       trunc(bytes/1073741824)||'G')))), 6, ' ') || '|' ||
       lpad(decode(cost,null,' ',
                decode(sign(cost-10000000), -1, cost||' ',
                decode(sign(cost-1000000000), -1, trunc(cost/1000000)||'M',
                       trunc(cost/1000000000)||'G'))), 8, ' ') || '|' ||
       lpad(decode(partition_start, 'ROW LOCATION', 'ROWID',
            decode(partition_start, 'KEY', 'KEY', decode(partition_start,
            'KEY(INLIST)', 'KEY(I)', decode(substr(partition_start, 1, 6),
            'NUMBER', substr(substr(partition_start, 8, 10), 1,
            length(substr(partition_start, 8, 10))-1),
            decode(partition_start,null,' ',partition_start)))))||' ', 7, ' ')|| '|' ||
       lpad(decode(partition_stop, 'ROW LOCATION', 'ROW L',
          decode(partition_stop, 'KEY', 'KEY', decode(partition_stop,
          'KEY(INLIST)', 'KEY(I)', decode(substr(partition_stop, 1, 6),
          'NUMBER', substr(substr(partition_stop, 8, 10), 1,
          length(substr(partition_stop, 8, 10))-1),
          decode(partition_stop,null,' ',partition_stop)))))||' ', 7, ' ')||'|' as "Explain plan"
from plan_table
start with id=0 and timestamp = (select max(timestamp) from plan_table
                                 where id=0 and nvl(statement_id, ' ') not like 'SYS_LE%')
                and nvl(statement_id, ' ') not like 'SYS_LE%'
connect by (prior id = parent_id
        and prior nvl(statement_id, ' ') = nvl(statement_id, ' ')
        and prior timestamp <= timestamp)
        or
       (prior nvl(object_name, ' ') like 'SYS_LE%' and prior nvl(object_name, ' ') = nvl(statement_id, ' ')
        and id = 0 and prior timestamp <= timestamp)
order siblings by id, position)
union all
select '------------------------------------------------------------------------------------------' from dual;

Note, that in 9.2, the utlxpls.sql script still exists, but it has now been re-written to query DBMS_XPLAN.

Obtaining trace files

SQL trace files can be obtained in a few ways. All of the techniques described below will create trace files in the operating system directory defined by the Oracle initialisation parameter user_dump_dest.

SQL_TRACE

SQL_TRACE should be familiar to most people who have had dealings with Oracle performance tuning. SQL_TRACE can be given the value of TRUE or FALSE and can be set for the current session or for any currently connected session (once the sid and serial# have been obtained from v$session).

One of the most important things to remember is to enable TIMED_STATISTICS, which enables the timing of events in v$system_event. Note, this defaults to TRUE in 10g, it was FALSE prior to this release of the database.

Enabling TIMED_STATISTICS for the "current" session :

SQL> ALTER SESSION SET TIMED_STATISTICS=TRUE

Enabling TIMED_STATISTICS for any currently connected session :

SQL> EXEC DBMS_SYSTEM.SET_BOOL_PARAM_IN_SESSION(sid, serial#, 'TIMED_STATISTICS', TRUE);

Once TIMED_STATISTICS is set to TRUE, there are many ways of enabling basic SQL_TRACE functionality, depending if you want to enable for the "current" session or any other session.

In order to enable basic SQL_TRACE for the "current" session :

SQL> ALTER SESSION SET SQL_TRACE=TRUE

Note, in 10g, SQL_TRACE is a deprecated parameter, Oracle recommends (via Metalink note 316889.1) that DBMS_SESSION should be used instead, i.e. :

SQL> EXEC DBMS_SESSION.SET_SQL_TRACE(TRUE);

Or, for any currently connected session, DBMS_SYSTEM or DBMS_MONITOR (10g only) can be used instead. Note, by default, DBMS_SYSTEM is only available as a SYSDBA user.

SQL> EXEC DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(:sid, :serial#, TRUE);

SQL> EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(:sid, :serial#);

For more information on the use of DBMS_MONITOR and DBMS_SESSION for extended SQL tracing, see Extended SQL_TRACE (event 10046 analysis).

For more information on SQL_TRACE, see http://download-uk.oracle.com/docs/cd/B19306_01/server.102/b14237/initparams204.htm#REFRN10208.

Extended SQL_TRACE (event 10046 analysis)

The Oracle Wait Interface is the most powerful tool for analysis performance bottlenecks. There are huge amounts of information on the web relating to it. In terms of SQL tracing, the event of most relevance is 10046, otherwise known as extended SQL_TRACE. 10046 analysis not only allows access to the execution plan of the query, but also, optionally, the values of any bind variables that were defined, as well as any wait events that Oracle incurred when executing the query. It is for this reason that 10046 analysis is considered to be the most effective way of determining performance bottlenecks in a SQL query.

Again, TIMED_STATISTICS is important for this to be of it's most valuable.

In order to enable 10046 event tracing for the current session :

SQL> ALTER SESSION SET EVENTS '10046 trace name context forever, level :level'

Or, for any connected session :

SQL> EXEC DBMS_SYSTEM.SET_EV(:sid, :serial#, 10046, :level, '');

The value of :level determines what level of tracing is to be undertaken. The following table explains the values and what trace information is recorded in the trace file.

level	Information included
1	Standard SQL_TRACE functionality
4	As level 1 plus tracing of bind variables
8	As level 1 plus wait events
12	As level 1 plus bind variables and wait events.

At 10g, both DBMS_MONITOR and DBMS_SESSION packages contain a procedure called SESSION_TRACE_ENABLE which allows specification of waits and / or binds as simple BOOLEAN parameters, so event 10046 analysis via ALTER SESSION SET EVENTS is largely superceded, i.e.

SQL> EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(:sid, :serial#, waits=>TRUE, binds=>TRUE);

SQL> EXEC DBMS_SESSION.SESSION_TRACE_ENABLE(waits=>TRUE, binds=>TRUE);

Note, not specifying the :sid and :serial# parameters enable extended SQL_TRACE for the current session, which is the same as using DBMS_SESSION :

SQL> EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(waits=>TRUE, binds=>TRUE);

Trace file analysis

In all cases, as mentioned above, trace files are created in the operating system directory specified in the user_dump_dest initialisation parameter. This file can either be tkprof'ed, specifying waits=yes if extended SQL tracing of at least level 8 has occurred (i.e. wait events have been traced) :

$ tkprof tracefile outputfile explain=user/pwd@db waits=yes

Note, tkprof will aggregate any wait events in the trace file in to a summary for that statement. This can be useful when trying to identify the type of operation that is taking the longest, such as communicating via SQL*Net, or doing index or table scans, however, it isn't a good idea if you need to identify precise wait events, such as which table is being scanned etc. In this situation, you have no choice but to analyse the "raw" trace file. Also, the values of any bind variables which have been traced by 10046 level 4 or 12 can only be seen in the trace file, tkprof does not display these (as of 10g).