So far, the previous examples have been on tracing the Execution of SQL statements and/or the Execution Plan used.
But what if you want to trace the Optimization --- identify how the Optimizer determined an "optimal" execution plan -- of an SQL statement.
Note : Pre-11g methods involved Event 10053. But as with Event 10046, I prefer to use methods where I don't have to use an Event Number but a Name. So, here I am not demonstrating the Event 10053 method itself.
Let's assume that there is a particular SQL identified as SQL_ID='b086mzzp82x7w' for which we need to know not just the Execution Plan but also how Oracle arrived at the Execution Plan.
Here's one way :
I have multiple SQLs executed in the session but am interested in the Optimization of only 1 SQL. Note how the specific SQL_ID is specified in the ALTER SESSION SET EVENTS command.
The resultant trace file is a very long trace file with a listing of all the instance/session parameters (hidden and public), all the Bug Fixes and the costing done for the SQL. The trace file captures only the SQL of interest, all the other SQLs in the same session are *not* in the trace file.
Here is an extract from the trace file :
The trace file captured only the SQL of interest. It also shows all the instance /session parameters and Bug Fixes that are relevant (these are very long lists so I have not reproduced them in entirety).
Note : The listing of parameters and Bug Fixes are very important in that if you have different execution plans in two different databases, you must verify the parameters and bug fixes and ensure that any differences in them are not relevant.
From the trace file, we can determine that this is the Execution Plan chosen :
The computation of Cost appears here :
Note how different Access Paths (Table Scan, Index FFS, IndexOnly,IndexRange) are all listed. The Best is shown as an IndexRange on the ALL_OBJ_M_L_CRTD_NDX with a Cost of 3599.20 More details appear here :
This is a very detailed listing for an SQL query on a single Table (no joins) and a single candidate index. Try running this with an SQL with Join of two or more tables and more than one candidate Index on each and see how complicated the Cost calculation becomes.
Note : To disable tracing in the session, I would run :
This sort of tracing can also be done with ALTER SYSTEM if you are not sure which session will be running the SQL_ID of interest and cannot interactively invoke the SQL from a private session.
.
.
.
But what if you want to trace the Optimization --- identify how the Optimizer determined an "optimal" execution plan -- of an SQL statement.
Note : Pre-11g methods involved Event 10053. But as with Event 10046, I prefer to use methods where I don't have to use an Event Number but a Name. So, here I am not demonstrating the Event 10053 method itself.
Let's assume that there is a particular SQL identified as SQL_ID='b086mzzp82x7w' for which we need to know not just the Execution Plan but also how Oracle arrived at the Execution Plan.
Here's one way :
SQL> alter session set events 'trace[rdbms.SQL_Optimizer.*][sql:b086mzzp82x7w]';
Session altered.
SQL> select 'abc' from dual;
'AB
---
abc
SQL> select count(*) from small_insert;
COUNT(*)
----------
4
SQL> select count(*) from all_objects_many_list
2 where created > sysdate-365;
COUNT(*)
----------
25548
SQL> select count(*) from all_objects_many_list;
COUNT(*)
----------
7254201
SQL> select value from v$diag_info where name = 'Default Trace File';
VALUE
------------------------------------------------------------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3102.trc
SQL>
I have multiple SQLs executed in the session but am interested in the Optimization of only 1 SQL. Note how the specific SQL_ID is specified in the ALTER SESSION SET EVENTS command.
The resultant trace file is a very long trace file with a listing of all the instance/session parameters (hidden and public), all the Bug Fixes and the costing done for the SQL. The trace file captures only the SQL of interest, all the other SQLs in the same session are *not* in the trace file.
Here is an extract from the trace file :
Registered qb: SEL$1 0x2173aea0 (PARSER)
---------------------
QUERY BLOCK SIGNATURE
---------------------
signature (): qb_name=SEL$1 nbfros=1 flg=0
fro(0): flg=4 objn=35014 hint_alias="ALL_OBJECTS_MANY_LIST"@"SEL$1"
SPM: statement not found in SMB
**************************
Automatic degree of parallelism (ADOP)
**************************
Automatic degree of parallelism is disabled: Parameter.
PM: Considering predicate move-around in query block SEL$1 (#0)
**************************
Predicate Move-Around (PM)
**************************
OPTIMIZER INFORMATION
******************************************
----- Current SQL Statement for this session (sql_id=b086mzzp82x7w) -----
select count(*) from all_objects_many_list
where created > sysdate-365
*******************************************
Legend
The following abbreviations are used by optimizer trace.
CBQT - cost-based query transformation
JPPD - join predicate push-down
OJPPD - old-style (non-cost-based) JPPD
FPD - filter push-down
PM - predicate move-around
CVM - complex view merging
SPJ - select-project-join
SJC - set join conversion
SU - subquery unnesting
OBYE - order by elimination
OST - old style star transformation
ST - new (cbqt) star transformation
CNT - count(col) to count(*) transformation
JE - Join Elimination
JF - join factorization
CBY - connect by
SLP - select list pruning
DP - distinct placement
qb - query block
LB - leaf blocks
DK - distinct keys
LB/K - average number of leaf blocks per key
DB/K - average number of data blocks per key
CLUF - clustering factor
NDV - number of distinct values
Resp - response cost
Card - cardinality
Resc - resource cost
NL - nested loops (join)
SM - sort merge (join)
HA - hash (join)
CPUSPEED - CPU Speed
IOTFRSPEED - I/O transfer speed
IOSEEKTIM - I/O seek time
SREADTIM - average single block read time
MREADTIM - average multiblock read time
MBRC - average multiblock read count
MAXTHR - maximum I/O system throughput
SLAVETHR - average slave I/O throughput
dmeth - distribution method
1: no partitioning required
2: value partitioned
4: right is random (round-robin)
128: left is random (round-robin)
8: broadcast right and partition left
16: broadcast left and partition right
32: partition left using partitioning of right
64: partition right using partitioning of left
256: run the join in serial
0: invalid distribution method
sel - selectivity
ptn - partition
***************************************
PARAMETERS USED BY THE OPTIMIZER
********************************
*************************************
PARAMETERS WITH ALTERED VALUES
Compilation Environment Dump
Bug Fix Control Environment
*************************************
PARAMETERS WITH DEFAULT VALUES
******************************
Compilation Environment Dump
........... long list of parameters and their values .........
..............................................................
.. followed by ...
........... long list of Bug Fixes that are enabled ..........
..............................................................
***************************************
PARAMETERS IN OPT_PARAM HINT
****************************
***************************************
Column Usage Monitoring is ON: tracking level = 1
***************************************
Considering Query Transformations on query block SEL$1 (#0)
**************************
Query transformations (QT)
**************************
JF: Checking validity of join factorization for query block SEL$1 (#0)
JF: Bypassed: not a UNION or UNION-ALL query block.
ST: not valid since star transformation parameter is FALSE
TE: Checking validity of table expansion for query block SEL$1 (#0)
TE: Bypassed: No partitioned table in query block.
CBQT bypassed for query block SEL$1 (#0): no complex view, sub-queries or UNION (ALL) queries.
CBQT: Validity checks failed for b086mzzp82x7w.
CSE: Considering common sub-expression elimination in query block SEL$1 (#0)
*************************
Common Subexpression elimination (CSE)
*************************
CSE: CSE not performed on query block SEL$1 (#0).
OBYE: Considering Order-by Elimination from view SEL$1 (#0)
***************************
Order-by elimination (OBYE)
***************************
OBYE: OBYE bypassed: no order by to eliminate.
CVM: Considering view merge in query block SEL$1 (#0)
OJE: Begin: find best directive for query block SEL$1 (#0)
OJE: End: finding best directive for query block SEL$1 (#0)
CNT: Considering count(col) to count(*) on query block SEL$1 (#0)
*************************
Count(col) to Count(*) (CNT)
*************************
CNT: COUNT() to COUNT(*) not done.
query block SEL$1 (#0) unchanged
Considering Query Transformations on query block SEL$1 (#0)
**************************
Query transformations (QT)
**************************
JF: Checking validity of join factorization for query block SEL$1 (#0)
JF: Bypassed: not a UNION or UNION-ALL query block.
ST: not valid since star transformation parameter is FALSE
TE: Checking validity of table expansion for query block SEL$1 (#0)
TE: Bypassed: No partitioned table in query block.
CBQT bypassed for query block SEL$1 (#0): no complex view, sub-queries or UNION (ALL) queries.
CBQT: Validity checks failed for b086mzzp82x7w.
CSE: Considering common sub-expression elimination in query block SEL$1 (#0)
*************************
Common Subexpression elimination (CSE)
*************************
CSE: CSE not performed on query block SEL$1 (#0).
SU: Considering subquery unnesting in query block SEL$1 (#0)
********************
Subquery Unnest (SU)
********************
SJC: Considering set-join conversion in query block SEL$1 (#0)
*************************
Set-Join Conversion (SJC)
*************************
SJC: not performed
PM: Considering predicate move-around in query block SEL$1 (#0)
**************************
Predicate Move-Around (PM)
**************************
PM: PM bypassed: Outer query contains no views.
PM: PM bypassed: Outer query contains no views.
query block SEL$1 (#0) unchanged
FPD: Considering simple filter push in query block SEL$1 (#0)
"ALL_OBJECTS_MANY_LIST"."CREATED">SYSDATE@!-365
try to generate transitive predicate from check constraints for query block SEL$1 (#0)
finally: "ALL_OBJECTS_MANY_LIST"."CREATED">SYSDATE@!-365
apadrv-start sqlid=12691376846034531580
:
call(in-use=2008, alloc=16344), compile(in-use=56240, alloc=58632), execution(in-use=2504, alloc=4032)
*******************************************
Peeked values of the binds in SQL statement
*******************************************
Final query after transformations:******* UNPARSED QUERY IS *******
SELECT COUNT(*) "COUNT(*)" FROM "HEMANT"."ALL_OBJECTS_MANY_LIST" "ALL_OBJECTS_MANY_LIST" WHERE "ALL_OBJECTS_MANY_LIST"."CREATED">SYSDATE@!-365
kkoqbc: optimizing query block SEL$1 (#0)
:
call(in-use=2056, alloc=16344), compile(in-use=57184, alloc=58632), execution(in-use=2504, alloc=4032)
kkoqbc-subheap (create addr=0x7f5f216ff9d0)
****************
QUERY BLOCK TEXT
****************
select count(*) from all_objects_many_list
where created > sysdate-365
---------------------
QUERY BLOCK SIGNATURE
---------------------
signature (optimizer): qb_name=SEL$1 nbfros=1 flg=0
fro(0): flg=0 objn=35014 hint_alias="ALL_OBJECTS_MANY_LIST"@"SEL$1"
-----------------------------
SYSTEM STATISTICS INFORMATION
-----------------------------
Using NOWORKLOAD Stats
CPUSPEEDNW: 937 millions instructions/sec (default is 100)
IOTFRSPEED: 4096 bytes per millisecond (default is 4096)
IOSEEKTIM: 10 milliseconds (default is 10)
MBRC: NO VALUE blocks (default is 8)
***************************************
BASE STATISTICAL INFORMATION
***********************
Table Stats::
Table: ALL_OBJECTS_MANY_LIST Alias: ALL_OBJECTS_MANY_LIST
#Rows: 7197952 #Blks: 98279 AvgRowLen: 93.00 ChainCnt: 0.00
Index Stats::
Index: ALL_OBJ_M_L_CRTD_NDX Col#: 7
LVLS: 2 #LB: 19093 #DK: 1232 LB/K: 15.00 DB/K: 351.00 CLUF: 432893.00
Access path analysis for ALL_OBJECTS_MANY_LIST
***************************************
SINGLE TABLE ACCESS PATH
Single Table Cardinality Estimation for ALL_OBJECTS_MANY_LIST[ALL_OBJECTS_MANY_LIST]
Column (#7): CREATED(
AvgLen: 8 NDV: 1232 Nulls: 0 Density: 0.000812 Min: 2455803 Max: 2457343
Table: ALL_OBJECTS_MANY_LIST Alias: ALL_OBJECTS_MANY_LIST
Card: Original: 7197952.000000 Rounded: 1346076 Computed: 1346075.60 Non Adjusted: 1346075.60
Access Path: TableScan
Cost: 27174.11 Resp: 27174.11 Degree: 0
Cost_io: 26619.00 Cost_cpu: 6242311042
Resp_io: 26619.00 Resp_cpu: 6242311042
Access Path: index (index (FFS))
Index: ALL_OBJ_M_L_CRTD_NDX
resc_io: 5173.00 resc_cpu: 4598699894
ix_sel: 0.000000 ix_sel_with_filters: 1.000000
Access Path: index (FFS)
Cost: 5581.95 Resp: 5581.95 Degree: 1
Cost_io: 5173.00 Cost_cpu: 4598699894
Resp_io: 5173.00 Resp_cpu: 4598699894
Access Path: index (IndexOnly)
Index: ALL_OBJ_M_L_CRTD_NDX
resc_io: 3573.00 resc_cpu: 294660105
ix_sel: 0.187008 ix_sel_with_filters: 0.187008
Cost: 3599.20 Resp: 3599.20 Degree: 1
Best:: AccessPath: IndexRange
Index: ALL_OBJ_M_L_CRTD_NDX
Cost: 3599.20 Degree: 1 Resp: 3599.20 Card: 1346075.60 Bytes: 0
***************************************
OPTIMIZER STATISTICS AND COMPUTATIONS
***************************************
GENERAL PLANS
***************************************
Considering cardinality-based initial join order.
Permutations for Starting Table :0
Join order[1]: ALL_OBJECTS_MANY_LIST[ALL_OBJECTS_MANY_LIST]#0
***********************
Best so far: Table#: 0 cost: 3599.2033 card: 1346075.6041 bytes: 10768608
***********************
(newjo-stop-1) k:0, spcnt:0, perm:1, maxperm:2000
*********************************
Number of join permutations tried: 1
*********************************
Enumerating distribution method (advanced)
Trying or-Expansion on query block SEL$1 (#0)
Transfer Optimizer annotations for query block SEL$1 (#0)
id=0 frofkks[i] (index start key) predicate="ALL_OBJECTS_MANY_LIST"."CREATED">SYSDATE@!-365
Final cost for query block SEL$1 (#0) - All Rows Plan:
Best join order: 1
Cost: 3599.2033 Degree: 1 Card: 1346076.0000 Bytes: 10768608
Resc: 3599.2033 Resc_io: 3573.0000 Resc_cpu: 294660105
Resp: 3599.2033 Resp_io: 3573.0000 Resc_cpu: 294660105
kkoqbc-subheap (delete addr=0x7f5f216ff9d0, in-use=26384, alloc=32840)
kkoqbc-end:
:
call(in-use=8664, alloc=49288), compile(in-use=59704, alloc=62776), execution(in-use=2504, alloc=4032)
kkoqbc: finish optimizing query block SEL$1 (#0)
apadrv-end
:
call(in-use=8664, alloc=49288), compile(in-use=60616, alloc=62776), execution(in-use=2504, alloc=4032)
Starting SQL statement dump
user_id=87 user_name=HEMANT module=SQL*Plus action=
sql_id=b086mzzp82x7w plan_hash_value=1689651126 problem_type=3
----- Current SQL Statement for this session (sql_id=b086mzzp82x7w) -----
select count(*) from all_objects_many_list
where created > sysdate-365
sql_text_length=71
sql=select count(*) from all_objects_many_list
where created > sysdate-365
----- Explain Plan Dump -----
----- Plan Table -----
============
Plan Table
============
-------------------------------------------------+-----------------------------------+
| Id | Operation | Name | Rows | Bytes | Cost | Time |
-------------------------------------------------+-----------------------------------+
| 0 | SELECT STATEMENT | | | | 3599 | |
| 1 | SORT AGGREGATE | | 1 | 8 | | |
| 2 | INDEX RANGE SCAN | ALL_OBJ_M_L_CRTD_NDX| 1315K | 10M | 3599 | 00:00:44 |
-------------------------------------------------+-----------------------------------+
Predicate Information:
----------------------
2 - access("CREATED">SYSDATE@!-365)
Content of other_xml column
===========================
db_version : 11.2.0.4
parse_schema : HEMANT
plan_hash : 1689651126
plan_hash_2 : 1742296710
Outline Data:
/*+
BEGIN_OUTLINE_DATA
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('11.2.0.4')
DB_VERSION('11.2.0.4')
ALL_ROWS
OUTLINE_LEAF(@"SEL$1")
INDEX(@"SEL$1" "ALL_OBJECTS_MANY_LIST"@"SEL$1" ("ALL_OBJECTS_MANY_LIST"."CREATED"))
END_OUTLINE_DATA
*/
Optimizer state dump:
Compilation Environment Dump
optimizer_mode_hinted = false
optimizer_features_hinted = 0.0.0
........... long list of parameters and their values .........
..............................................................
.. followed by ...
........... long list of Bug Fixes that are enabled ..........
..............................................................
Query Block Registry:
SEL$1 0x2173aea0 (PARSER) [FINAL]
:
call(in-use=11728, alloc=49288), compile(in-use=90576, alloc=152120), execution(in-use=6440, alloc=8088)
End of Optimizer State Dump
Dumping Hints
=============
====================== END SQL Statement Dump ======================
The trace file captured only the SQL of interest. It also shows all the instance /session parameters and Bug Fixes that are relevant (these are very long lists so I have not reproduced them in entirety).
Note : The listing of parameters and Bug Fixes are very important in that if you have different execution plans in two different databases, you must verify the parameters and bug fixes and ensure that any differences in them are not relevant.
From the trace file, we can determine that this is the Execution Plan chosen :
-------------------------------------------------+-----------------------------------+
| Id | Operation | Name | Rows | Bytes | Cost | Time |
-------------------------------------------------+-----------------------------------+
| 0 | SELECT STATEMENT | | | | 3599 | |
| 1 | SORT AGGREGATE | | 1 | 8 | | |
| 2 | INDEX RANGE SCAN | ALL_OBJ_M_L_CRTD_NDX| 1315K | 10M | 3599 | 00:00:44 |
-------------------------------------------------+-----------------------------------+
Predicate Information:
----------------------
2 - access("CREATED">SYSDATE@!-365)
Content of other_xml column
===========================
db_version : 11.2.0.4
parse_schema : HEMANT
plan_hash : 1689651126
plan_hash_2 : 1742296710
Outline Data:
/*+
BEGIN_OUTLINE_DATA
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE('11.2.0.4')
DB_VERSION('11.2.0.4')
ALL_ROWS
OUTLINE_LEAF(@"SEL$1")
INDEX(@"SEL$1" "ALL_OBJECTS_MANY_LIST"@"SEL$1" ("ALL_OBJECTS_MANY_LIST"."CREATED"))
END_OUTLINE_DATA
*/
The computation of Cost appears here :
SINGLE TABLE ACCESS PATH
Single Table Cardinality Estimation for ALL_OBJECTS_MANY_LIST[ALL_OBJECTS_MANY_LIST]
Column (#7): CREATED(
AvgLen: 8 NDV: 1232 Nulls: 0 Density: 0.000812 Min: 2455803 Max: 2457343
Table: ALL_OBJECTS_MANY_LIST Alias: ALL_OBJECTS_MANY_LIST
Card: Original: 7197952.000000 Rounded: 1346076 Computed: 1346075.60 Non Adjusted: 1346075.60
Access Path: TableScan
Cost: 27174.11 Resp: 27174.11 Degree: 0
Cost_io: 26619.00 Cost_cpu: 6242311042
Resp_io: 26619.00 Resp_cpu: 6242311042
Access Path: index (index (FFS))
Index: ALL_OBJ_M_L_CRTD_NDX
resc_io: 5173.00 resc_cpu: 4598699894
ix_sel: 0.000000 ix_sel_with_filters: 1.000000
Access Path: index (FFS)
Cost: 5581.95 Resp: 5581.95 Degree: 1
Cost_io: 5173.00 Cost_cpu: 4598699894
Resp_io: 5173.00 Resp_cpu: 4598699894
Access Path: index (IndexOnly)
Index: ALL_OBJ_M_L_CRTD_NDX
resc_io: 3573.00 resc_cpu: 294660105
ix_sel: 0.187008 ix_sel_with_filters: 0.187008
Cost: 3599.20 Resp: 3599.20 Degree: 1
Best:: AccessPath: IndexRange
Index: ALL_OBJ_M_L_CRTD_NDX
Cost: 3599.20 Degree: 1 Resp: 3599.20 Card: 1346075.60 Bytes: 0
Note how different Access Paths (Table Scan, Index FFS, IndexOnly,IndexRange) are all listed. The Best is shown as an IndexRange on the ALL_OBJ_M_L_CRTD_NDX with a Cost of 3599.20 More details appear here :
OPTIMIZER STATISTICS AND COMPUTATIONS *************************************** GENERAL PLANS *************************************** Considering cardinality-based initial join order. Permutations for Starting Table :0 Join order[1]: ALL_OBJECTS_MANY_LIST[ALL_OBJECTS_MANY_LIST]#0 *********************** Best so far: Table#: 0 cost: 3599.2033 card: 1346075.6041 bytes: 10768608 *********************** (newjo-stop-1) k:0, spcnt:0, perm:1, maxperm:2000 ********************************* Number of join permutations tried: 1 ********************************* Enumerating distribution method (advanced) Trying or-Expansion on query block SEL$1 (#0) Transfer Optimizer annotations for query block SEL$1 (#0) id=0 frofkks[i] (index start key) predicate="ALL_OBJECTS_MANY_LIST"."CREATED">SYSDATE@!-365 Final cost for query block SEL$1 (#0) - All Rows Plan: Best join order: 1 Cost: 3599.2033 Degree: 1 Card: 1346076.0000 Bytes: 10768608 Resc: 3599.2033 Resc_io: 3573.0000 Resc_cpu: 294660105 Resp: 3599.2033 Resp_io: 3573.0000 Resc_cpu: 294660105
This is a very detailed listing for an SQL query on a single Table (no joins) and a single candidate index. Try running this with an SQL with Join of two or more tables and more than one candidate Index on each and see how complicated the Cost calculation becomes.
Note : To disable tracing in the session, I would run :
ALTER SESSION SET EVENTS 'trace[rdbms.SQL_Optimizer.*] off';
This sort of tracing can also be done with ALTER SYSTEM if you are not sure which session will be running the SQL_ID of interest and cannot interactively invoke the SQL from a private session.
.
.
.