Search My Oracle Blog

Custom Search

07 February, 2016

Trace Files -- 11b : Using DBMS_SQLDIAG to trace the Optimization of an SQL Statement

My previous blogpost covered using ALTER SYSTEM/SESSION to set tracing for a specific SQL_ID that has been determined in advance.   The SQL may be executed in the future after the ALTER SYSTEM/SESSION.

Here is a method for an SQL that has already been executed.

SQL> select count(*) from all_objects_many_list
  2  where created > sysdate-365;

  COUNT(*)
----------
     25548

SQL> begin
  2  dbms_sqldiag.dump_trace(p_sql_id=>'b086mzzp82x7w',
  3                          p_component=>'Optimizer',
  4                         p_file_id=>'OPT_TRACE_b086mzzp82x7w');
  5  end;
  6  /

PL/SQL procedure successfully completed.

SQL> 
SQL> select value from v$diag_info where name = 'Default Trace File';

VALUE
------------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_2987_OPT_TRACE_b086mzzp82x7w.trc

SQL> 


Let's review the trace file.

Registered qb: SEL$1 0x99b9000 (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
SPM: statement not a candidate for auto-capture

**************************
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=0b1t991khf449) -----
/* SQL Analyze(148,0) */ select count(*) from all_objects_many_list
where created > sysdate-365
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x6be0d530       145  package body SYS.DBMS_SQLTUNE_INTERNAL
0x6be0d530     12098  package body SYS.DBMS_SQLTUNE_INTERNAL
0x6be6b738      1229  package body SYS.DBMS_SQLDIAG
0x6becaea8         2  anonymous block
*******************************************
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
is_recur_flags                      = 8
Bug Fix Control Environment


  *************************************
  PARAMETERS WITH DEFAULT VALUES
  ******************************
Compilation Environment Dump
optimizer_mode_hinted               = false
optimizer_features_hinted           = 0.0.0
parallel_execution_enabled          = true
parallel_query_forced_dop           = 0
parallel_dml_forced_dop             = 0
parallel_ddl_forced_degree          = 0
parallel_ddl_forced_instances       = 0
_query_rewrite_fudge                = 90
optimizer_features_enable           = 11.2.0.4
_optimizer_search_limit             = 5
.... continued to a long list of parameters ........
....................................................
Bug Fix Control Environment
    fix  3834770 = 1
    fix  3746511 = enabled
    fix  4519016 = enabled
.... continued to a long list of bug fixes ........
...................................................
 ***************************************
  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 0b1t991khf449.
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 0b1t991khf449.
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=398332482954924169
  :
    call(in-use=2008, alloc=16344), compile(in-use=56240, alloc=59416), execution(in-use=2456, 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=57320, alloc=59416), execution(in-use=2456, alloc=4032)

kkoqbc-subheap (create addr=0x7f4409c4fb18)
****************
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)


And here is the actual information about how the Costing is done and Execution Plan determined.

***************************************
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: 1313133  Computed: 1313133.42  Non Adjusted: 1313133.42
  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: 3486.00  resc_cpu: 287452140
    ix_sel: 0.182432  ix_sel_with_filters: 0.182432
    Cost: 3511.56  Resp: 3511.56  Degree: 1
  Best:: AccessPath: IndexRange
  Index: ALL_OBJ_M_L_CRTD_NDX
         Cost: 3511.56  Degree: 1  Resp: 3511.56  Card: 1313133.42  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: 3511.5623  card: 1313133.4203  bytes: 10505064
***********************
(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: 3511.5623  Degree: 1  Card: 1313133.0000  Bytes: 10505064
  Resc: 3511.5623  Resc_io: 3486.0000  Resc_cpu: 287452140
  Resp: 3511.5623  Resp_io: 3486.0000  Resc_cpu: 287452140
kkoqbc-subheap (delete addr=0x7f4409c4fb18, in-use=26384, alloc=32840)
kkoqbc-end:
        :
    call(in-use=8664, alloc=49288), compile(in-use=59856, alloc=63560), execution(in-use=2456, alloc=4032)

kkoqbc: finish optimizing query block SEL$1 (#0)
apadrv-end
          :
    call(in-use=8664, alloc=49288), compile(in-use=60768, alloc=63560), execution(in-use=2456, alloc=4032)


Starting SQL statement dump

user_id=87 user_name=HEMANT module=SQL*Plus action=
sql_id=0b1t991khf449 plan_hash_value=1689651126 problem_type=3
----- Current SQL Statement for this session (sql_id=0b1t991khf449) -----
/* SQL Analyze(148,0) */ select count(*) from all_objects_many_list
where created > sysdate-365
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x6be0d530       145  package body SYS.DBMS_SQLTUNE_INTERNAL
0x6be0d530     12098  package body SYS.DBMS_SQLTUNE_INTERNAL
0x6be6b738      1229  package body SYS.DBMS_SQLDIAG
0x6becaea8         2  anonymous block
sql_text_length=96
sql=/* SQL Analyze(148,0) */ 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   |                     |       |       |  3512 |           |
| 1   |  SORT AGGREGATE    |                     |     1 |     8 |       |           |
| 2   |   INDEX RANGE SCAN | ALL_OBJ_M_L_CRTD_NDX| 1282K |   10M |  3512 |  00:00:43 |
-------------------------------------------------+-----------------------------------+
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

*** 2016-02-07 21:29:15.838
      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
parallel_execution_enabled          = true
parallel_query_forced_dop           = 0
parallel_dml_forced_dop             = 0
parallel_ddl_forced_degree          = 0
parallel_ddl_forced_instances       = 0
_query_rewrite_fudge                = 90
optimizer_features_enable           = 11.2.0.4
_optimizer_search_limit             = 5
...... long list of optimizer parameters  ...........
.....................................................
Bug Fix Control Environment
    fix  3834770 = 1
    fix  3746511 = enabled
    fix  4519016 = enabled
...... long list of Bug Fixes .......................
.....................................................

Query Block Registry:
SEL$1 0x99b9000 (PARSER) [FINAL]

:
    call(in-use=11728, alloc=49288), compile(in-use=90704, alloc=155568), execution(in-use=6408, alloc=8088)

End of Optimizer State Dump
Dumping Hints
=============
====================== END SQL Statement Dump ======================


So, this is also a supported method.  This DBMS_SQLDIAG package is available from 11.2
Unfortunately, however, DUMP_TRACE is not documented !  (see the 11.2 documentation on DBMS_SQLDIAG).

Note : If the SQL Statement and/or Plan have already been aged out / purged from the Shared Pool , a DUMP_TRACE would, obviously, not be able to print anything.
.
.
.

31 January, 2016

Trace Files -- 11 : Tracing the Optimization of an SQL Statement

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 :

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



24 January, 2016

Trace Files -- 10c : Query and DML (INSERT)

In the previous posts, I have traced either
SELECT
or
INSERT or UPDATE or DELETE
statements

I have pointed out that the block statistics are reported as "FETCH" statistics for SELECTs and "EXECUTE" statistics for the DMLs

What if we have an INSERT ... AS SELECT ?

SQL ID: 5pf0puy1pmcvc Plan Hash: 2393429040

insert into all_objects_many_list select * from all_objects_short_list


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.01       0.01          0          0          0           0
Execute      1      0.73      16.19        166       1655      14104       28114
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.74      16.21        166       1655      14104       28114

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 87
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=1766 pr=166 pw=0 time=16204380 us)
     28114      28114      28114   TABLE ACCESS FULL ALL_OBJECTS_SHORT_LIST (cr=579 pr=0 pw=0 time=127463 us cost=158 size=2614881 card=28117)


insert into all_objects_many_list
select * from all_objects_short_list
where rownum < 11

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          6         11          10
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          6         11          10

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 87
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=6 pr=0 pw=0 time=494 us)
        10         10         10   COUNT STOPKEY (cr=3 pr=0 pw=0 time=167 us)
        10         10         10    TABLE ACCESS FULL ALL_OBJECTS_SHORT_LIST (cr=3 pr=0 pw=0 time=83 us cost=158 size=2614881 card=28117)


Since it is an INSERT statement, the block statistics are reported against EXECUTE (nothing reported against the FETCH), even though the Row Source Operations section shows use Table Access (i.e. SELECT) against the ALL_OBJECTS_SHORT_LIST table. Also note, as we have seen in the previous trace on INSERTs, the target table does not get reported in the Row Source Operations.

Here's another example.

SQL ID: 5fgnrpgk3uumc Plan Hash: 2703984749

insert into all_objects_many_list select * from dba_objects


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.04       0.25          0          0          0           0
Execute      1      0.63       3.94         82       2622      13386       28125
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.67       4.20         82       2622      13386       28125

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 87
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  LOAD TABLE CONVENTIONAL  (cr=2736 pr=82 pw=0 time=3954384 us)
     28125      28125      28125   VIEW  DBA_OBJECTS (cr=360 pr=2 pw=0 time=1898588 us cost=105 size=5820219 card=28117)
     28125      28125      28125    UNION-ALL  (cr=360 pr=2 pw=0 time=1735711 us)
         0          0          0     TABLE ACCESS BY INDEX ROWID SUM$ (cr=2 pr=2 pw=0 time=65154 us cost=1 size=11 card=1)
         1          1          1      INDEX UNIQUE SCAN I_SUM$_1 (cr=1 pr=1 pw=0 time=61664 us cost=0 size=0 card=1)(object id 986)
         0          0          0     TABLE ACCESS BY INDEX ROWID OBJ$ (cr=0 pr=0 pw=0 time=0 us cost=3 size=25 card=1)
         0          0          0      INDEX RANGE SCAN I_OBJ1 (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)(object id 36)
     28124      28124      28124     FILTER  (cr=354 pr=0 pw=0 time=1094905 us)
     28124      28124      28124      HASH JOIN  (cr=354 pr=0 pw=0 time=911322 us cost=102 size=3402036 card=28116)
        68         68         68       TABLE ACCESS FULL USER$ (cr=5 pr=0 pw=0 time=328 us cost=3 size=1224 card=68)
     28124      28124      28124       HASH JOIN  (cr=349 pr=0 pw=0 time=612040 us cost=99 size=2895948 card=28116)
        68         68         68        INDEX FULL SCAN I_USER2 (cr=1 pr=0 pw=0 time=159 us cost=1 size=1496 card=68)(object id 47)
     28124      28124      28124        TABLE ACCESS FULL OBJ$ (cr=348 pr=0 pw=0 time=147446 us cost=98 size=2277396 card=28116)
         0          0          0      NESTED LOOPS  (cr=0 pr=0 pw=0 time=0 us cost=2 size=30 card=1)
         0          0          0       INDEX SKIP SCAN I_USER2 (cr=0 pr=0 pw=0 time=0 us cost=1 size=20 card=1)(object id 47)
         0          0          0       INDEX RANGE SCAN I_OBJ4 (cr=0 pr=0 pw=0 time=0 us cost=1 size=10 card=1)(object id 39)
         1          1          1     NESTED LOOPS  (cr=4 pr=0 pw=0 time=262 us cost=3 size=38 card=1)
         1          1          1      TABLE ACCESS FULL LINK$ (cr=2 pr=0 pw=0 time=180 us cost=2 size=20 card=1)
         1          1          1      TABLE ACCESS CLUSTER USER$ (cr=2 pr=0 pw=0 time=50 us cost=1 size=18 card=1)
         1          1          1       INDEX UNIQUE SCAN I_USER# (cr=1 pr=0 pw=0 time=21 us cost=0 size=0 card=1)(object id 11)

Only the source tables are reported in the Row Source Operations section. All the blocks are reported in the EXECUTE phase. Why does the "query" count in the EXECUTE statistics differ from the "cr" count reported for the LOAD TABLE CONVENTIONAL. (LOAD TABLE CONVENTIONAL indicates a regular non-direct-path INSERT).
.
.
.

Aggregated by orafaq.com

Aggregated by orafaq.com
This blog is being aggregated by orafaq.com