Striving for Optimal Performance

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.

Last week I had to analyze a strange performance problem. Since the cause/solution was somehow surprising, at least for me, I thought to share it with you.

Let me start by quickly describing the setup and what was done to reproduce the problem:

• Database version: Oracle Database 11g Enterprise Edition Release 11.1.0.6.0 (64-bit)
• Operating system: Solaris 10 (SPARC)
• To simulate a load job, a simple SQL*Plus script that executes a COPY command is used. Its purpose is to load about 100,000 rows in a table. Let’s call this table T1.
• All modifications in T1 have to be logged into another table. Let’s call it T2. For this purpose, on T1 there are triggers that insert one row into T2 for each inserted, deleted and updated row.

The strange thing was that the rate of the inserts performed by the script decreased over time. In fact, while at the beginning of the processing about 500 rows per second were inserted into T1 (and, therefore, T2), at the end of the processing only about 50 rows per second were processed.

The first thing I did to find out what the problem was is to trace one run by enabling SQL trace. This analysis pointed out that two SQL statements (the ones inserting data into T1 and T2) were responsible for most of the elapsed time. This is not a surprise, of course. The interesting thing was that most of the time was spent on CPU.

Since the rate of the inserts decreased over time, I extracted from the trace file all the lines providing information about the executions of the INSERT statement on T1 and loaded that data into Excel. Then, I created one chart for each performance figure. From all of them the following, that shows the amount of CPU used for every single execution, was the most interesting. In fact, it shows that while at the beginning of the processing one insert uses about 30 milliseconds of CPU, at the end it uses about 300 milliseconds of CPU for doing the same work. Note that all other charts did not show such a behavior. For example, the number of PIO and LIO were exactly the same at the beginning and at the end of the processing.

Since the trace file was not able to provide further information to investigate the problem, I started looking at V$SESSTAT. The aim was to find another statistic experiencing a similar increase. The search pointed out that the statistic “session uga memory” was also increasing during the processing. In fact, while at the beginning of the processing the session was using about 5MB of UGA, at the end of the processing about 110MB were used. This is strange and, as far as I know, there is no good reason for such a behavior. Hence, it was time to review the code of the triggers. While doing so I noticed, by chance, that a trigger was also available on T2 (the table used to store the log about all modifications). The strange thing was its definition:

CREATE OR REPLACE TRIGGER t2 AFTER INSERT ON t2 FOR EACH ROW
BEGIN
  /* execute the referential-integrity actions */
  DECLARE
    NUMROWS INTEGER;
  BEGIN
    numrows:=1;
  END;
END;

As you can see the trigger does nothing. Apparently, it exists just because triggers are used to implement integrity constraints (something you should avoid, by the way…) and, as a result, they were automatically created for each table. And, in case of T2, there is no constraint to check.

Since the trigger is pointless, I disabled it. After that, surprisingly, it was no longer possible to reproduce the problem! The following chart, created in the same way as the previous one, shows that without the trigger on T2 the CPU utilization is constant during the whole processing.

Therefore, for some unknown reasons, the pointless trigger was the cause of the problem.

By the way, once the trigger was disabled also the UGA memory was no longer increasing. Hence, to me it seems that the customer hit a bug…

Yesterday, I received the following question from a TVD$XTAT user:

XCTEND lines are reported as “COMMIT/ROLLBACK (synthetic)”. Using Goolge and Metalink I can’t find any other resources describing “COMMIT/ROLLBACK (synthetic)”. This term seems not be widely used, although Hotsos uses the same term. Could you please elaborate what exactly that is and why it possibly happens?

To understand what “synthetic” means, let’s have a look to two small trace files.The first one is generated by tracing the execution of the following SQL statements in SQL*Plus:

UPDATE scott.emp SET sal = sal*1.15;
COMMIT;

The relevant part of the trace file is the following. Notice that:

• There are two cursors: the first one is the update, the second one is the commit.
• In the second one, because it is a commit, between the PARSE and the EXEC lines there is a XCTEND line. Note that the database engine emmits a XCTEND line for every commit or rollback. To differentiate the two, the attribute “rlbk” is used: 0=commit, 1=rollback.
• The “log file sync” wait is associated to the second cursor, the commit.

=====================
PARSING IN CURSOR #3 len=35 dep=0 uid=84 oct=6 lid=84 tim=1250674381587415 hv=950048100 ad='38e58340' sqlid='crk1wdnwa15b4'
UPDATE scott.emp SET sal = sal*1.15
END OF STMT
PARSE #3:c=0,e=338,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1494045816,tim=1250674381587404
EXEC #3:c=2999,e=2831,p=0,cr=7,cu=4,mis=0,r=14,dep=0,og=1,plh=1494045816,tim=1250674381590917
STAT #3 id=1 cnt=0 pid=0 pos=1 obj=0 op='UPDATE  EMP (cr=7 pr=0 pw=0 time=0 us)'
STAT #3 id=2 cnt=14 pid=1 pos=1 obj=73268 op='TABLE ACCESS FULL EMP (cr=7 pr=0 pw=0 time=14 us cost=3 size=70 card=14)'
WAIT #3: nam='SQL*Net message to client' ela= 11 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1250674381592362
WAIT #3: nam='SQL*Net message from client' ela= 1812 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1250674381594288
CLOSE #3:c=0,e=28,dep=0,type=0,tim=1250674381594476
=====================
PARSING IN CURSOR #2 len=6 dep=0 uid=84 oct=44 lid=84 tim=1250674381594857 hv=255718823 ad='0' sqlid='8ggw94h7mvxd7'
COMMIT
END OF STMT
PARSE #2:c=0,e=146,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=1250674381594814
XCTEND rlbk=0, rd_only=0, tim=1250674381595557
EXEC #2:c=1000,e=740,p=0,cr=0,cu=1,mis=0,r=0,dep=0,og=0,plh=0,tim=1250674381596086
WAIT #2: nam='log file sync' ela= 1974 buffer#=1980 p2=0 p3=0 obj#=-1 tim=1250674381598390
WAIT #2: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1250674381598664
WAIT #2: nam='SQL*Net message from client' ela= 2770 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1250674381601434
CLOSE #2:c=0,e=17,dep=0,type=3,tim=1250674381601595
=====================

The second trace file is generated by tracing the execution of the same operations from a Java program. The following is the method that contains the update and the commit:

private static void test(Connection connection) throws Exception
{
  Statement statement = connection.createStatement();
  statement.execute("UPDATE scott.emp SET sal = sal * 1.15");
  statement.close();
  connection.commit();
}

The relevant part of the trace file is the following. Notice that:

• There is only one cursor: the update. No cursor related to the commit is available.
• Just after the CLOSE line there is a XCTEND line with the attribute “rlbk” set to 0. Obviously a commit was performed.
• The “log file sync” wait is associated to cursor number 0. Note that the database engine associate to cursor number 0 all lines that cannot be associated to other cursors. In this case a cursor with the commit statement is missing, hence it is not possible to associate the wait to it.

=====================
PARSING IN CURSOR #2 len=37 dep=0 uid=84 oct=6 lid=84 tim=1250673660406187 hv=517367075 ad='38d919e4' sqlid='cc8438wgdct93'
UPDATE scott.emp SET sal = sal * 1.15
END OF STMT
PARSE #2:c=39994,e=40693,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1494045816,tim=1250673660406167
EXEC #2:c=17997,e=18116,p=0,cr=7,cu=4,mis=0,r=14,dep=0,og=1,plh=1494045816,tim=1250673660427450
STAT #2 id=1 cnt=0 pid=0 pos=1 obj=0 op='UPDATE  EMP (cr=7 pr=0 pw=0 time=0 us)'
STAT #2 id=2 cnt=14 pid=1 pos=1 obj=73268 op='TABLE ACCESS FULL EMP (cr=7 pr=0 pw=0 time=5 us cost=3 size=70 card=14)'
WAIT #2: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1250673660432401
WAIT #2: nam='SQL*Net message from client' ela= 12925 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1250673660446291
CLOSE #2:c=0,e=45,dep=0,type=0,tim=1250673660447335
XCTEND rlbk=0, rd_only=0, tim=1250673660449381
WAIT #0: nam='log file sync' ela= 1325 buffer#=1217 p2=0 p3=0 obj#=-1 tim=1250673660454674
WAIT #0: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=1250673660454885
=====================

The interesting thing to note about the second case is that a commit was performed without executing a COMMIT statement. This is possible because at the OCI level a commit can be performed by calling the function OCITransCommit. In other words, without having to execute a statement.

Now, back to the question. When TVD$XTAT processes a trace file like the second one, it automatically generates a cursor related to the commit operation. The text of the cursor will be “COMMIT (synthetic)”. So, the term “synthetic” is only added to point out that it is a generated cursor. In addition, TVD$XTAT also associate the waits associated to the cursor 0 to the generated cursor. This is very important because in some situations, for example when commits are executed very often or when long rollbacks are executed, the time needed for the commit/rollback is not negligible. As a result, if they were not accounted, the unaccounted-for time could be relevant.

BTW, it is not a coincidence that the Method R Profiler (a.k.a. Hotsos Profiler) and TVD$XTAT uses the same term. I fact, while comparing the two profilers, I noticed that in Method R Profiler the generated statements were called “synthetic”. I found the idea good and since I was looking for a method to mark such statements as well, I borrowed their term.

This is just a short note to point out that I just uploaded under the section Downloadable Files of TOP a new version of TVD$XTAT. Not only I introduced some new features, but I also fixed a couple of major bugs related to memory consumption and poor performance…

The detailed change log since Beta 8 is the following:

• Added formatting for bind variable values of type DATE
• Added support for several execution plans for a single cursor
• Added number of executions and hash value to execution plans
• Added detection of incomplete execution plans
• Added support for RPC bind variables
• Added command-line option to control logging level
• Added warning for 11.1.0.7 trace files (because of bug# 7522002 timing information might be wrong)
• Improved data type detection to distinguish VARCHAR2 from NVARCHAR2 and CHAR from NCHAR
• Improved handling of incorrectly formatted input lines
• Changed logging formatter (time is displayed with the following pattern HH:mm:ss)
• Reduced memory utilization for the processing of large trace files
• Fix to prevent poor performance for the processing of large trace files
• Fix to replace special characters not supported by XML (the unicode character FFFD is used istead of the special ones)
• Fix in template to correctly handle space character in SQL text and bind variable values
• Fix to ignore timestamp lines not generated by SQL trace

As always, your feedback is welcome!

As of 11g the package DBMS_MONITOR provides an important new feature. The aim of this post is to describe not only what this feature is, but also why it is important.

To illustrate how the new feature works, two things are necessary. First, a small table:

SQL> SELECT * FROM t;

         N
----------
         1
         2
         3
         4
         5

Second, an anonymous PL/SQL block. About it notice that:

• Three queries using the very same cursor are executed.
• The number of fetched rows is different for each execution.
• Array processing is used to fetch all data in a single call.
• The package DBMS_MONITOR is used to enable and disable SQL trace.

DECLARE
  l_cursor INTEGER;
  l_n dbms_sql.number_table;
  l_retval INTEGER;
BEGIN
  dbms_monitor.session_trace_enable;
  l_cursor := dbms_sql.open_cursor;
  dbms_sql.parse(l_cursor, 'SELECT n FROM t WHERE n <= :1', 1);
  dbms_sql.define_array(l_cursor, 1, l_n, 5, 1);
  FOR i IN 1..3
  LOOP
    dbms_sql.bind_variable(l_cursor, ':1', i);
    l_retval := dbms_sql.execute(l_cursor);
    l_retval := dbms_sql.fetch_rows(l_cursor);
  END LOOP;
  dbms_sql.close_cursor(l_cursor);
  dbms_monitor.session_trace_disable;
END;

Now, let’s start by executing the anonymous PL/SQL block in 10.2.0.4. In that version, the content of the generated trace file is the following. Notice that:

• One single parse (PARSE line) was performed.
• Three executions (EXEC lines) were performed.
• Three fetches (FETCH lines) were performed. The first one fetched 1 row (value “r”), the second one fetched 2 rows, and the third one fetched 3 rows.
• The information about the execution plan (STAT line; notice that I manually removed the runtime statistics and query optimizer estimations to keep the output more readable) was written in the trace file only when the cursor was closed. According to it, 6 rows were fetched (value “cnt”). In other words, 1+2+3.

PARSING IN CURSOR #18 len=29 dep=1 uid=28 oct=3 lid=28 tim=1204698401458764 hv=2067044879 ad='72de8330'
SELECT n FROM t WHERE n <= :1
END OF STMT
PARSE #18:c=0,e=427,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=1204698401458760
EXEC #18:c=1000,e=912,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=1204698401509992
FETCH #18:c=0,e=68,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=1,tim=1204698401510109
EXEC #18:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1204698401510184
FETCH #18:c=0,e=26,p=0,cr=3,cu=0,mis=0,r=2,dep=1,og=1,tim=1204698401510234
EXEC #18:c=0,e=11,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1204698401510290
FETCH #18:c=0,e=19,p=0,cr=3,cu=0,mis=0,r=3,dep=1,og=1,tim=1204698401510333
STAT #18 id=1 cnt=6 pid=0 pos=1 obj=15665 op='TABLE ACCESS FULL T'

And now, let’s execute it in 11.1.0.6. In this case notice that:

• The same number of parse, execute and fetch calls as in 10.2.0.4 were performed.
• The information about the execution plan was written in the trace file just after the first execution and not when the statement was closed. For this reason, according to it, only 1 row was fetched.

PARSING IN CURSOR #4 len=29 dep=1 uid=30 oct=3 lid=30 tim=1233611735664091 hv=2067044879 ad='6ae30880' sqlid='cxa35s1xm96hg'
SELECT n FROM t WHERE n <= :1
END OF STMT
PARSE #4:c=4000,e=118923,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=1233611735664086
EXEC #4:c=1999,e=28275,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=1233611735779067
FETCH #4:c=0,e=88,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=1,tim=1233611735779278
STAT #4 id=1 cnt=1 pid=0 pos=1 obj=17363 op='TABLE ACCESS FULL T'
EXEC #4:c=0,e=43,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1233611735795372
FETCH #4:c=0,e=45,p=0,cr=3,cu=0,mis=0,r=2,dep=1,og=1,tim=1233611735795449
EXEC #4:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1233611735795509
FETCH #4:c=0,e=18,p=0,cr=3,cu=0,mis=0,r=3,dep=1,og=1,tim=1233611735795552

Why this difference?

It is because, as of 11g, the procedures in the package dbms_monitor that are used to enable SQL trace accept an additional parameter: PLAN_STAT. As written in the documentation, this parameter is used to specify the frequency at which the row source statistics (i.e. information about execution plans) are written in trace files. The accepted values are the following (the default value is NULL):

• NEVER: no information about the execution plan is written in trace files.
• FIRST_EXECUTION (equivalent to NULL): information about the execution plan is written just after the first execution.
• ALL_EXECUTIONS: information about the execution plan is written for every execution.

Therefore, when the parameter PLAN_STAT is set to ALL_EXECUTIONS, the content of the trace file is the following:

PARSING IN CURSOR #9 len=29 dep=1 uid=30 oct=3 lid=30 tim=1233613010415243 hv=2067044879 ad='6ae30880' sqlid='cxa35s1xm96hg'
SELECT n FROM t WHERE n <= :1
END OF STMT
PARSE #9:c=2000,e=28550,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=1233613010415239
EXEC #9:c=2000,e=21361,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=1233613010500308
FETCH #9:c=0,e=70,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=1,tim=1233613010500878
STAT #9 id=1 cnt=1 pid=0 pos=1 obj=17364 op='TABLE ACCESS FULL T'
EXEC #9:c=999,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1233613010506855
FETCH #9:c=0,e=24,p=0,cr=3,cu=0,mis=0,r=2,dep=1,og=1,tim=1233613010506906
STAT #9 id=1 cnt=2 pid=0 pos=1 obj=17364 op='TABLE ACCESS FULL T'
EXEC #9:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1233613010507425
FETCH #9:c=0,e=27,p=0,cr=3,cu=0,mis=0,r=3,dep=1,og=1,tim=1233613010507479
STAT #9 id=1 cnt=3 pid=0 pos=1 obj=17364 op='TABLE ACCESS FULL T'

Why is this feature important?

It is because up to 10g, especially for application keeping cursors open for a “long time”, it is not unusual to see trace files not containing information about execution plans for every cursor. Since that information is critical to diagnose performance problems, it might be a major issue. As of 11g, however, the trace files should always contain this critical information (except if the value NEVER is used, of course).