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).