As of Oracle Database 11g the DBMS_SQLTUNE package provides the SELECT_SQL_TRACE function. Its purpose is to load the content of a SQL trace file into a SQL tuning set. But, as it often happens, a feature can be (mis)used for another purpose. The aim of this post is to show how to take advantage of this function to display through SQL statements the content of a SQL trace file.

Note that the SELECT_SQL_TRACE function is not available in version 11.1.0.6. Refer to the MOS note 790806.1 for additional information. Hence, the code shown in this post works as of 11.1.0.7 only.

First of all, let’s setup the scene.

• Create the necessary database objects and gather object statistics:

SQL> CREATE TABLE t
  2  AS
  3  SELECT rownum AS id, rpad('*',1000,'*') AS pad
  4  FROM dual
  5  CONNECT BY level <= 10000
  6  ORDER BY dbms_random.value;

SQL> ALTER TABLE t ADD CONSTRAINT t_pk PRIMARY KEY (id);

SQL> BEGIN
  2    dbms_stats.gather_table_stats(
  3      ownname          => user,
  4      tabname          => 't',
  5      estimate_percent => 100,
  6      method_opt       => 'for all columns size 1'
  7    );
  8  END;
  9  /

• Enable SQL trace (if you are asking yourself why I specify the PLAN_STAT parameter, have a look to this post):

SQL> execute dbms_monitor.session_trace_enable(binds => TRUE, plan_stat => 'ALL_EXECUTIONS')

• Run some queries:

SQL> EXECUTE :id := 10;

SQL> SELECT count(pad) FROM t WHERE id < :id;

COUNT(PAD)
----------
         9

SQL> EXECUTE :id := 990;

SQL> SELECT count(pad) FROM t WHERE id < :id;

COUNT(PAD)
----------
       989

SQL> SELECT count(pad) FROM t WHERE id < :id;

COUNT(PAD)
----------
       989

SQL> EXECUTE :id := 20;

SQL> SELECT count(pad) FROM t WHERE id < :id;

COUNT(PAD)
----------
        19

SQL> SELECT sum(id) FROM t;

   SUM(ID)
----------
  50005000

• Disable SQL trace and retrieve the name of the SQL trace file:

SQL> execute dbms_monitor.session_trace_disable

SQL> SELECT value
  2  FROM v$diag_info
  3  WHERE name = 'Default Trace File';

VALUE
-------------------------------------------------------------------
/u00/app/oracle/diag/rdbms/dba112/DBA112/trace/DBA112_ora_26790.trc

• Create a directory to read the SQL trace file through SQL statements

SQL> CREATE DIRECTORY trace AS '/u00/app/oracle/diag/rdbms/dba112/DBA112/trace/';

Now that we have a SQL trace file, let’s see how we can read its content with some simple queries and what kind of information we can extract.

• Retrieve a list of SQL statements executed by the current user (to exclude the recursive SQL statements executed by SYS) including their elapsed time and number of executions:

SQL> SELECT sql_id,
  2         sum(elapsed_time) AS elapsed_time,
  3         sum(executions) AS executions,
  4         round(sum(elapsed_time)/sum(executions)) AS elapsed_time_per_execution
  5  FROM table(dbms_sqltune.select_sql_trace(
  6               directory => 'TRACE',
  7               file_name => 'DBA112_ora_26790.trc',
  8               select_mode => 2 -- all executions
  9            )) t
 10  WHERE parsing_schema_name = user
 11  GROUP BY sql_id
 12  ORDER BY elapsed_time DESC;

SQL_ID        ELAPSED_TIME EXECUTIONS ELAPSED_TIME_PER_EXECUTION
------------- ------------ ---------- --------------------------
asth1mx10aygn       249757          4                      62439
6tgnxwpymddqc         4200          1                       4200

• Retrieve the text of a particular SQL statement:

SQL> SELECT sql_text
  2  FROM table(dbms_sqltune.select_sql_trace(
  3               directory => 'TRACE',
  4               file_name => 'DBA112_ora_26790.trc',
  5               select_mode => 1 -- only first execution
  6            )) t
  7  WHERE sql_id = 'asth1mx10aygn';

SQL_TEXT
---------------------------------------
SELECT count(pad) FROM t WHERE id < :id

• Retrieve more execution statistics about a particular SQL statement:

SQL> SELECT plan_hash_value, executions, fetches, elapsed_time, cpu_time, disk_reads, buffer_gets, rows_processed
  2  FROM table(dbms_sqltune.select_sql_trace(
  3               directory => 'TRACE',
  4               file_name => 'DBA112_ora_26790.trc',
  5               select_mode => 2 -- all executions
  6            )) t
  7  WHERE sql_id = 'asth1mx10aygn'
  8  ORDER BY elapsed_time DESC;

PLAN_HASH_VALUE EXECUTIONS    FETCHES ELAPSED_TIME   CPU_TIME DISK_READS BUFFER_GETS ROWS_PROCESSED
--------------- ---------- ---------- ------------ ---------- ---------- ----------- --------------
     4294967295          1          2       129056     127981        731         992              1
     4294967295          1          2       113667     112982        691        1434              1
     4294967295          1          2         5993       6999         11          11              1
     4294967295          1          2         1041       1000          0          21              1

• Retrieve the value of the bind variables used to execute a particular SQL statement:

SQL> SELECT elapsed_time,
  2         value(b).gettypename() AS type,
  3         value(b).accessnumber() AS value
  4  FROM table(dbms_sqltune.select_sql_trace(
  5               directory => 'TRACE',
  6               file_name => 'DBA112_ora_26790.trc',
  7               select_mode => 2 -- all executions
  8            )) t,
  9       table(bind_list) b
 10  WHERE sql_id = 'asth1mx10aygn'
 11  ORDER BY elapsed_time DESC;

ELAPSED_TIME TYPE       VALUE
------------ ---------- -----
      129056 SYS.NUMBER   990
      113667 SYS.NUMBER   990
        5993 SYS.NUMBER    10
        1041 SYS.NUMBER    20

Even though everything seems fine, there is an error in the output of one of the queries. Specifically, the hash value of the execution plan is not always the right one (the same value is used for all executions). In fact, because of extended cursor sharing (a.k.a. adaptive cursor sharing) several execution plans were used. This can be confirmed by analyzing the trace file with TKPROF (or another analyzer like TVD$XTAT). In this case the TKPROF output, generated with the AGGREGATE option set to "NO" provides the following information (notice that the hash value of the third execution is different):

...
SQL ID: asth1mx10aygn
Plan Hash: 4270555908
SELECT count(pad) FROM t WHERE id < :id
...
SQL ID: asth1mx10aygn
Plan Hash: 4270555908
SELECT count(pad) FROM t WHERE id < :id
...
SQL ID: asth1mx10aygn
Plan Hash: 2966233522
SELECT count(pad) FROM t WHERE id < :id
...
SQL ID: asth1mx10aygn
Plan Hash: 4270555908
SELECT count(pad) FROM t WHERE id < :id
...

The other information that can be retrieved through the SELECT_SQL_TRACE function is the execution plan. Unfortunately, extracting it directly through the function is inconvenient. The reason is that you should do the formatting yourself. Much easier is to load the information into a SQL tuning set and, then, to use the DBMS_XPLAN package to show its content. The following example illustrates this:

SQL> DECLARE
  2    c sys_refcursor;
  3  BEGIN
  4    dbms_sqltune.create_sqlset('TEST');
  5    OPEN c FOR
  6      SELECT value(t)
  7      FROM table(dbms_sqltune.select_sql_trace(
  8               directory => 'TRACE',
  9               file_name => 'DBA112_ora_26790.trc',
 10               select_mode => 2 -- all executions
 11                )) t;
 12    dbms_sqltune.load_sqlset('TEST', c);
 13    CLOSE c;
 14  END;
 15  /

SQL> SELECT *
  2  FROM table(dbms_xplan.display_sqlset(
  3               sqlset_name => 'TEST',
  4               sql_id => 'asth1mx10aygn'
  5            ));

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------
SQL Tuning Set Name: TEST
SQL Tuning Set Owner: CHA
SQL_ID: asth1mx10aygn
SQL Text: SELECT count(pad) FROM t WHERE id < :id
-----------------------------------------------------------------------------

-----------------------------------------------------------------------------
| Id  | Operation                    | Name                 | Bytes | Cost  |
-----------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                      |       |       |
|   1 |  SORT AGGREGATE              |                      |       |       |
|   2 |   TABLE ACCESS BY INDEX ROWID| UNKNOWN_OBJECT_90222 |  9045 |    11 |
|   3 |    INDEX RANGE SCAN          | UNKNOWN_OBJECT_90223 |       |     2 |
-----------------------------------------------------------------------------

Notice that also in this case only one execution plan is shown.

All in all, this is an interesting feature. For sure it does not replace a profiler (mainly because the wait events are not shown), but it might be useful in some situations.