Striving for Optimal Performance

During an evolution the database engine compares the performance of two execution plans. The aim is to find out which one provides the better performance. For that purpose it has to run the SQL statement on which the SQL plan baseline is based and compare some execution statistics. The following output of the DBMS_SPM.EVOLVE_SQL_PLAN_BASELINE function shows which statistics are compared.

Plan was verified: Time used .06 seconds.
Plan passed performance criterion: 360.12 times better than baseline plan.
Plan was changed to an accepted plan.

                          Baseline Plan      Test Plan       Stats Ratio
                          -------------      ---------       -----------
Execution Status:              COMPLETE       COMPLETE
Rows Processed:                     100            100
Elapsed Time(ms):                 2.173           .033             65.85
CPU Time(ms):                     2.444              0
Buffer Gets:                        720              2               360
Physical Read Requests:               0              0
Physical Write Requests:              0              0
Physical Read Bytes:                  0              0
Physical Write Bytes:                 0              0
Executions:                           1              1

For queries a regular execution can be performed. But, what happens for INSERT/UPDATE/MERGE/DELETE statements? Do the SQL engine really execute them and modify data?

To answer these questions let’s have a look to an example based on a DELETE statement…

• Setup a table used for the test:

SQL> CREATE TABLE t (id, n, pad, CONSTRAINT t_pk PRIMARY KEY (id))
  2  AS
  3  SELECT rownum, mod(rownum,100), rpad('*',500,'*')
  4  FROM dual
  5  CONNECT BY level <= 10000;

SQL> execute dbms_stats.gather_table_stats(ownname => user, tabname => 't', method_opt => 'for all columns size 254')

• Create a SQL plan baseline:

SQL> ALTER SESSION SET optimizer_capture_sql_plan_baselines = TRUE;

SQL> DELETE t WHERE n = 42;

SQL> ROLLBACK;

SQL> DELETE t WHERE n = 42;

SQL> ROLLBACK;

SQL> ALTER SESSION SET optimizer_capture_sql_plan_baselines = FALSE;

• Add a non-accepted execution plan to the SQL plan baseline:

SQL> CREATE INDEX i ON t (n);

SQL> DELETE t WHERE n = 42;

SQL> ROLLBACK;

SQL> DELETE t WHERE n = 42;

SQL> ROLLBACK;

• Display the content of the SQL plan baseline (notice that two execution plans are available):

SQL> SELECT * FROM table(dbms_xplan.display_sql_plan_baseline('SYS_SQL_373d78bbba048c24', NULL, 'basic'));

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

--------------------------------------------------------------------------------
SQL handle: SYS_SQL_373d78bbba048c24
SQL text: DELETE t WHERE n = 42
--------------------------------------------------------------------------------

--------------------------------------------------------------------------------
Plan name: SQL_PLAN_3fgbsrfx093143bad20a0         Plan id: 1001201824
Enabled: YES     Fixed: NO      Accepted: YES     Origin: AUTO-CAPTURE
--------------------------------------------------------------------------------

Plan hash value: 3335594643

-----------------------------------
| Id  | Operation          | Name |
-----------------------------------
|   0 | DELETE STATEMENT   |      |
|   1 |  DELETE            | T    |
|   2 |   TABLE ACCESS FULL| T    |
-----------------------------------

--------------------------------------------------------------------------------
Plan name: SQL_PLAN_3fgbsrfx093144198692b         Plan id: 1100507435
Enabled: YES     Fixed: NO      Accepted: NO      Origin: AUTO-CAPTURE
--------------------------------------------------------------------------------

Plan hash value: 1582806765

----------------------------------
| Id  | Operation         | Name |
----------------------------------
|   0 | DELETE STATEMENT  |      |
|   1 |  DELETE           | T    |
|   2 |   INDEX RANGE SCAN| I    |
----------------------------------

• Trace the evolution to find out what happens (notice that I deleted the output of the function because it is the one it is shown at the top of this post):

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

SQL> SELECT dbms_spm.evolve_sql_plan_baseline(
  2           sql_handle => 'SYS_SQL_373d78bbba048c24',
  3           plan_name  => '',
  4           time_limit => 10,
  5           verify     => 'yes',
  6           commit     => 'yes'
  7         )
  8  FROM dual;

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_17200.trc

Now that the trace file was generated, let’s have a look to its content. The relevant parts are two: the first one is related to the execution of the accepted execution plan, and the second one is related to the execution of the non-accepted one.

PARSING IN CURSOR #11 len=45 dep=1 uid=90 oct=7 lid=90 tim=1275524159625080 hv=4077337184 ad='325c9f10' sqlid='5fwyncmthffm0'
/* SQL Analyze(25,0) */ DELETE t WHERE n = 42
END OF STMT
PARSE #11:c=1000,e=652,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=1001201824,tim=1275524159625078
EXEC #11:c=4999,e=5670,p=0,cr=720,cu=0,mis=0,r=0,dep=1,og=1,plh=1001201824,tim=1275524159630752
EXEC #11:c=2000,e=1718,p=0,cr=720,cu=0,mis=0,r=0,dep=1,og=1,plh=1001201824,tim=1275524159632613
EXEC #11:c=2000,e=1511,p=0,cr=720,cu=0,mis=0,r=0,dep=1,og=1,plh=1001201824,tim=1275524159634156
EXEC #11:c=2000,e=1542,p=0,cr=720,cu=0,mis=0,r=0,dep=1,og=1,plh=1001201824,tim=1275524159636144
EXEC #11:c=2000,e=1552,p=0,cr=720,cu=0,mis=0,r=0,dep=1,og=1,plh=1001201824,tim=1275524159638151
EXEC #11:c=3998,e=4015,p=0,cr=720,cu=0,mis=0,r=0,dep=1,og=1,plh=1001201824,tim=1275524159642613
EXEC #11:c=3000,e=2905,p=0,cr=720,cu=0,mis=0,r=0,dep=1,og=1,plh=1001201824,tim=1275524159645549
EXEC #11:c=2000,e=1506,p=0,cr=720,cu=0,mis=0,r=0,dep=1,og=1,plh=1001201824,tim=1275524159647151
EXEC #11:c=2000,e=1562,p=0,cr=720,cu=0,mis=0,r=0,dep=1,og=1,plh=1001201824,tim=1275524159649160
EXEC #11:c=2999,e=2440,p=0,cr=720,cu=0,mis=0,r=0,dep=1,og=1,plh=1001201824,tim=1275524159652037
CLOSE #11:c=0,e=3,dep=1,type=0,tim=1275524159652065

PARSING IN CURSOR #5 len=45 dep=1 uid=90 oct=7 lid=90 tim=1275524159657503 hv=4077337184 ad='325c9f10' sqlid='5fwyncmthffm0'
/* SQL Analyze(25,0) */ DELETE t WHERE n = 42
END OF STMT
PARSE #5:c=1000,e=859,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=1100507435,tim=1275524159657499
EXEC #5:c=0,e=52,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=1,plh=1100507435,tim=1275524159657625
EXEC #5:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=1,plh=1100507435,tim=1275524159657647
EXEC #5:c=0,e=31,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=1,plh=1100507435,tim=1275524159657972
EXEC #5:c=0,e=5,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=1,plh=1100507435,tim=1275524159658071
EXEC #5:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=1,plh=1100507435,tim=1275524159658071
EXEC #5:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=1,plh=1100507435,tim=1275524159658071
EXEC #5:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=1,plh=1100507435,tim=1275524159658071
EXEC #5:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=1,plh=1100507435,tim=1275524159658071
EXEC #5:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=1,plh=1100507435,tim=1275524159658071
EXEC #5:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=1,plh=1100507435,tim=1275524159658071
CLOSE #5:c=0,e=0,dep=1,type=0,tim=1275524159658071

In the previous output notice that:

• The PLH attribute of the EXEC lines shows that two execution plans are used.
• Each execution plan was executed 10 times (in practice the number varies according to the elapsed time; i.e. for longer executions a single run might be enough to determine whether an execution plan has to be accepted).
• Even though I set the PLAN_STAT parameter to ALL_EXECUTIONS (if you don’t know what the PLAN_STAT parameter is for, have a look to this post) the STAT lines (the execution plan) are not available in the trace file.

According to this information the SQL statement is executed. But, if you check the table after the evolution, the data is still there. And that, honestly, is not an option! In addition, no ROLLBACK is executed (no XCTEND lines are present in the trace file). So, it seems that the SQL statement is not executed.

What I really miss in the trace file are the execution plans associated to the executions to check what the different operations of the execution plan did. The only way I found to have them, it is to add the GATHER_PLAN_STATISTICS hint into the SQL statement itself (also setting the STATISTICS_LEVEL parameter and checking a view like V$SQL_PLAN_STATISTICS_ALL did not help). The content of the trace file, formatted by TVD$XTAT, is the following:

Optimizer Mode       ALL_ROWS
Hash Value           1001201824
Number of Executions 10

        Rows Operation
------------ ---------------------------------------------------------------------------------------
           0 DELETE  T (cr=720 pr=25 pw=0 time=0 us)
           0   TABLE ACCESS FULL T (cr=720 pr=25 pw=0 time=0 us cost=84 size=700 card=100)

Optimizer Mode       ALL_ROWS
Hash Value           1100507435
Number of Executions 10

        Rows Operation
------------ ---------------------------------------------------------------------------------------
           0 DELETE  T (cr=2 pr=0 pw=0 time=0 us)
           0   INDEX RANGE SCAN I (cr=2 pr=0 pw=0 time=0 us cost=1 size=700 card=100) (object id 93840)

Notice that while the number of logical reads (CR attribute) matches the report generated by the evolution, the number of rows returned by both steps of the execution plans is 0. And that, even though the index range scan should return 100 rows.

In summary, during an evolution the SQL engine processes the SQL statements in a special way. The data is accessed, but not modified. Hence, SQL statements are only partially executed. I do not regard this fact as a problem, though. In fact, the operations that modify data should always perform the same work independently on how the data to be modified is located (in the example given here, either with a full table scan or an index range scan).

The aim of this post is to describe a strange (buggy) situation that I observed recently. But before doing that, I shortly summarize what a parent cursor and a child cursor are as well as when they can be shared. By the way, I borrowed this description from the pages 20/21 of my book. Hence, if you are interested in more information about this topic refer to it…

The result of a parse operation is a parent cursor and a child cursor stored in the library cache.

The key information related to a parent cursor is the text of the SQL statement. Therefore, several SQL statements share the same parent cursor if their text is exactly the same (note that there is at least an exception to this, specifically when cursor sharing is used). In the following example, four SQL statements are executed. Two have the same text. Two others differ only because of lowercase and uppercase letters or blanks. Through the V$SQLAREA view, it is possible to confirm that three distinct parent cursors were created.

SQL> ALTER SYSTEM FLUSH SHARED_POOL;

SQL> SELECT * FROM t WHERE n = 1234;

SQL> select * from t where n = 1234;

SQL> SELECT * FROM t WHERE n=1234;

SQL> SELECT * FROM t WHERE n = 1234;

SQL> SELECT sql_id, sql_text, executions
  2  FROM v$sqlarea
  3  WHERE sql_text LIKE '%1234';

SQL_ID        SQL_TEXT                          EXECUTIONS
------------- --------------------------------- ----------
2254m1487jg50 select * from t where n = 1234             1
g9y3jtp6ru4cb SELECT * FROM t WHERE n = 1234             2
7n8p5s2udfdsn SELECT * FROM t WHERE n=1234               1

The key information related to a child cursor is the execution plan and the execution environment related to it. The execution environment is important because if it changes, the execution plan might change as well. As a result, several SQL statements are able to share the same child cursor only if they share the same parent cursor and their execution environments are compatible. To illustrate, the same SQL statement is executed with two different values of the initialization OPTIMIZER_MODE parameter. The result is that a single parent cursor and two child cursors are created.

SQL> ALTER SESSION SET optimizer_mode = all_rows;

SQL> SELECT count(*) FROM t;

COUNT(*)
----------
      1000

SQL> ALTER SESSION SET optimizer_mode = first_rows_10;

SQL> SELECT count(*) FROM t;

COUNT(*)
----------
      1000

SQL> SELECT sql_id, child_number, sql_text, optimizer_mode, plan_hash_value
  2  FROM v$sql
  3  WHERE sql_id = (SELECT prev_sql_id
  4  FROM v$session
  5  WHERE sid = sys_context('userenv','sid'));

SQL_ID        CHILD_NUMBER SQL_TEXT               OPTIMIZER_MODE PLAN_HASH_VALUE
------------- ------------ ---------------------- -------------- ---------------
5tjqf7sx5dzmj            0 SELECT count(*) FROM t ALL_ROWS            2966233522
5tjqf7sx5dzmj            1 SELECT count(*) FROM t FIRST_ROWS          2966233522

To know which mismatch led to several child cursors, you can query the V$SQL_SHARED_CURSOR view.

SQL> SELECT child_number, optimizer_mode_mismatch
  2  FROM v$sql_shared_cursor
  3  WHERE sql_id = '5tjqf7sx5dzmj';

CHILD_NUMBER OPTIMIZER_MODE_MISMATCH
------------ -----------------------
           0 N
           1 Y

So far, so good… Now, let’s see what’s strange…

The interesting thing to point out about the previous example is that while I set FIRST_ROWS_10 as optimizer mode, the V$SQL view displayed the value FIRST_ROWS. Mhmm… That’s strange… They are two different optimizer modes. They cannot be considered equivalent. What are the implications? It is just the view that provides the wrong information or the database engine is able to share the same child cursor even with two different values of the OPTIMIZER_MODE parameter? Let’s try it with FIRST_ROWS (i.e. without “_10”)…

 SQL> ALTER SESSION SET optimizer_mode = first_rows;

SQL> SELECT sql_id, child_number, sql_text, optimizer_mode, executions
  2  FROM v$sql
  3  WHERE sql_id = (SELECT prev_sql_id
  4                  FROM v$session
  5                  WHERE sid = sys_context('userenv','sid'));

SQL_ID        CHILD_NUMBER SQL_TEXT                          OPTIMIZER_MODE EXECUTIONS
------------- ------------ --------------------------------- -------------- ----------
5tjqf7sx5dzmj            0 SELECT count(*) FROM t            ALL_ROWS                1
5tjqf7sx5dzmj            1 SELECT count(*) FROM t            FIRST_ROWS              2

Oh, damn! Even though the OPTIMIZER MODE is set to a different value the same child cursor is used. Since in this particular situation the execution plans associated to both child cursors are the same (their hash value are equal), it’s not a real problem. But, in practice, it might be possible that two different optimizer modes lead to different execution plans. The following example illustrates this.

• Build a table for the test:

SQL> CREATE TABLE t AS
  2  SELECT rownum AS id, rpad('*',500,'*') AS pad
  3  FROM dual
  4  CONNECT BY level <= 1000;

SQL> CREATE UNIQUE INDEX i ON t (id);

SQL> execute dbms_stats.gather_table_stats(user, 'T')

• Show that different values of the OPTIMIZER_MODE parameter lead to different execution plans:

SQL> ALTER SESSION SET optimizer_mode = FIRST_ROWS_1;

SQL> EXPLAIN PLAN FOR SELECT * FROM t WHERE id <= 500;

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

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------
Plan hash value: 242607798

------------------------------------------------------------------------------------
| Id  | Operation                   | Name | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |      |     3 |  1515 |     3   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T    |     3 |  1515 |     3   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | I    |       |       |     2   (0)| 00:00:01 |
------------------------------------------------------------------------------------

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

   2 - access("ID"<=500)

SQL> ALTER SESSION SET optimizer_mode = FIRST_ROWS_1000;

SQL> EXPLAIN PLAN FOR SELECT * FROM t WHERE id <= 500;

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

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------
Plan hash value: 1601196873

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |   500 |   246K|    10   (0)| 00:00:01 |
|*  1 |  TABLE ACCESS FULL| T    |   500 |   246K|    10   (0)| 00:00:01 |
--------------------------------------------------------------------------

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

   1 - filter("ID"<=500)

• Execute the test query with both values of the OPTIMIZER_MODE parameter:

SQL> ALTER SYSTEM FLUSH SHARED_POOL;

SQL> ALTER SESSION SET optimizer_mode = FIRST_ROWS_1;

SQL> SELECT * FROM t WHERE id <= 500;

        ID PAD
---------- ----------
         1 **********
         2 **********
…
       499 **********
       500 **********

SQL> ALTER SESSION SET optimizer_mode = FIRST_ROWS_1000;

SQL> SELECT * FROM t WHERE id <= 500;

        ID PAD
---------- ----------
         1 **********
         2 **********
…
       499 **********
       500 **********

• Show that a single execution plan was used for both executions:

SQL> SELECT * FROM table(dbms_xplan.display_cursor(NULL,NULL));

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------
SQL_ID  2vw03p929jzgz, child number 0
-------------------------------------
SELECT * FROM t WHERE id <= 500

Plan hash value: 242607798

------------------------------------------------------------------------------------
| Id  | Operation                   | Name | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |      |       |       |     3 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| T    |     3 |  1515 |     3   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | I    |       |       |     2   (0)| 00:00:01 |
------------------------------------------------------------------------------------

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

   2 - access("ID"<=500)

SQL> SELECT sql_id, child_number, executions, optimizer_mode
  2  FROM v$sql
  3  WHERE sql_id = '2vw03p929jzgz';

SQL_ID        CHILD_NUMBER EXECUTIONS OPTIMIZER_MODE
------------- ------------ ---------- --------------
2vw03p929jzgz            0          2 FIRST_ROWS

Even though it is not very likely that this bug (yes, in my opinion something like this cannot be considered a restriction of the implementation…) has an impact on a production system, I really don’t understand why the developers didn’t implement it correctly. It should not be that difficult to manage a byte containing the information about the used optimizer mode! Note that this is not the only case where something like that happens with the first rows optimizer mode. For example, also in a trace file generated through SQL trace no difference is made between the old and the new first row optimizer. So, it seams that they really got it wrong.

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.