Search

Top 60 Oracle Blogs

Recent comments

[Oracle] DB Optimizer Part XII - Revealing SQL Plan Directive details for existing/loaded cursor from CBO (and SQL Dynamic Sampling Services) trace

Introduction

The idea for this blog post is based on a recent Twitter discussion with Martin Berger, Martin Bach and Mauro Pagano about revealing SQL Plan Directive details for an existing cursor as walking through the standard Oracle data dictionary views can be very time consuming/slow and there are still some details missing about the dynamic sampling task itself, even if you have found what you are looking for.

 

You can check out my blog post about SQL Plan Directives, if you are not familiar with it yet. However my blog post is also a little bit out-dated as Oracle has changed some (state) behavior between version 12.1.0.1 and 12.1.0.2. Franck Pachot has published a series about SQL Plan Directives (with main focus on version 12.1.0.2) in his blog - so it may be good idea to start with the basic concepts in my blog post and then go to Franck's blog posts. Please check the reference section for his series.

 

So what is the issue i am talking about?

Let's assume somebody has executed a SQL statement and this statement has used a SQL Plan Directive. The SQL ran slow due to a bad execution plan and you want to figure out, if the SQL Plan Directive is the reason for this. Unfortunately DBMS_XPLAN.DISPLAY_CURSOR does not provide you any information about which SQL plan directive was used (for more details please check my Tweet about it) as this information is not stored with the cursor - it only says "SQL Plan Directive used". Of course you can use the "EXPLAIN PLAN" approach for this as Franck Pachot stated in one of his blog posts, but EXPLAIN PLAN has several limitations (e.g. treats all binds as VARCHAR2, no bind peeking, etc.) and can not be used in many cases accordingly.



Now you can start to query the Oracle dictionary views (e.g. DBA_SQL_PLAN_DIRECTIVES or DBA_SQL_PLAN_DIR_OBJECTS) and try to figure out which SQL Plan directive was used and how it influenced your execution plan, but this can be very slow as Mauro pointed out and you still got no information about the dynamic sampling details.



The solution to this? Good old cost based optimizer (10053 aka. Wolfgang) trace plus some additional SQL Dynamic Sampling Services trace.





Demo for revealing SQL Plan Directive details with traces

The following demo was run on an Oracle database (12.1.0.2) on Solaris 11.2 (x86_64) and with an Oracle schema called "TEST". I have used the same base table and data set as in one my previous blog posts.



Create the base table and data set

SQL> create table DYNTEST (COUNTRY VARCHAR2(40), WERKS VARCHAR(20), TEXT VARCHAR(4000));



SQL> begin

for i in 1 .. 1000 loop

  insert into DYNTEST values ('DE', '1200', 'TEXT');

end loop;

for i in 1 .. 50 loop

  insert into DYNTEST values ('DE', '4200', 'TEXT');

end loop;

for i in 1 .. 500 loop

  insert into DYNTEST values ('DE', '2200', 'TEXT');

end loop;

for i in 1 .. 5000 loop

  insert into DYNTEST values ('US', '3400', 'TEXT');

end loop;

for i in 1 .. 100 loop

  insert into DYNTEST values ('DE', '6200', 'TEXT');

end loop;

for i in 1 .. 480 loop

  insert into DYNTEST values ('ZH', '9000', 'TEXT');

end loop;

for i in 1 .. 520 loop

  insert into DYNTEST values ('CH', '5000', 'TEXT');

end loop;

commit;

end;

/



SQL> exec DBMS_STATS.GATHER_TABLE_STATS('TEST', 'DYNTEST', method_opt => 'FOR ALL COLUMNS SIZE 1');

 

 

SQL and SQL Plan Directive + object state

SQL> select /*+ gather_plan_statistics */ * from DYNTEST where COUNTRY = 'DE' and WERKS = '1200';

 

SQL> select * from table (DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALL ALLSTATS OUTLINE PEEKED_BINDS LAST'));

DBMS_XPLAN.png

 

SQL> select OBJECT_NAME, OBJECT_ID, DATA_OBJECT_ID from DBA_OBJECTS where OWNER = 'TEST';

OBJECT_NAME          OBJECT_ID DATA_OBJECT_ID

-------------------- ---------- --------------

DYNTEST              91171      91171

 

SQL> select * from DBA_SQL_PLAN_DIR_OBJECTS where OWNER = 'TEST';

DBA_SQL_PLAN_DIR_OBJECTS.png

 

SQL> select * from DBA_SQL_PLAN_DIRECTIVES where DIRECTIVE_ID = 13237011096450186301;

DBA_SQL_PLAN_DIRECTIVES.png

 

SQL> select TYPE, STATUS, BUCKET_NO, HASH, NAME, CACHE_ID, CACHE_KEY from V$RESULT_CACHE_OBJECTS;

 

RESULT_CACHE_OBJECTS.png

 

So we have a SQL plan directive for our query (SQL ID "6jr7pwrk2tszg") and the dynamic sampling result is cached in the result cache for 3600 seconds (default behavior). There maybe some issues with this behavior, but this should not be our topic here. Please check the reference section, if you are interested into the details of such issues.

However this is usually the point when you got a call that the query ran slow and now you want to get more details about the SQL plan directive and its dynamic sampling (result).

 

 

Generate cost based optimizer (10053) trace for SQL statement in cursor cache

This is usually done by running the PL/SQL procedure DBMS_SQLDIAG.DUMP_TRACE as you do not need to re-execute the SQL statement. However be sure that you use the correct component (= "Optimizer"), otherwise the cost based optimizer trace (with component "Compiler") stops at "kkoadsSetTimeSlice: #candTabs=1 slice=2500" and you do not get the details you want.

 

SQL> exec dbms_sqldiag.dump_trace('6jr7pwrk2tszg',0,'Optimizer','CBO_Optimizer_Trace_Test');

=====================================

SPD: BEGIN context at statement level

=====================================

Stmt: ******* UNPARSED QUERY IS *******

SELECT "DYNTEST"."COUNTRY" "COUNTRY","DYNTEST"."WERKS" "WERKS","DYNTEST"."TEXT" "TEXT" FROM "TEST"."DYNTEST" "DYNTEST" WHERE "DYNTEST"."COUNTRY"='DE' AND "DYNTEST"."WERKS"='1200'

Objects referenced in the statement

  DYNTEST[DYNTEST] 91171, type = 1

Objects in the hash table

  #ff0000;">Hash table Object 91171, type = 1, ownerid = 15196265155538183602:

    Dynamic Sampling Directives at location 1:

       #ff0000;">dirid = 13237011096450186301, state = 1, flags = 1, #ff0000;">loc = 1 {EC(91171)[1, 2]}

Return code in qosdInitDirCtx: ENBLD

===================================

SPD: END context at statement level

===================================

***************************************

BASE STATISTICAL INFORMATION

***********************

Table Stats::

  Table: DYNTEST  Alias: DYNTEST

  #Rows: 7650  SSZ: 0  LGR: 0  #Blks:  20  AvgRowLen:  13.00  NEB: 0  ChainCnt:  0.00  SPC: 0  RFL: 0  RNF: 0  CBK: 0  CHR: 0  KQDFLG: 1

  #IMCUs: 0  IMCRowCnt: 0  IMCJournalRowCnt: 0  #IMCBlocks: 0  IMCQuotient: 0.000000

=======================================

SPD: BEGIN context at query block level

=======================================

Query Block SEL$1 (#0)

Applicable DS directives:

#ff0000;">   dirid = 13237011096450186301, state = 1, flags = 1, #ff0000;">loc = 1 {EC(91171)[1, 2]}

Checking valid directives for the query block

  SPD: Return code in qosdDSDirSetup: NODIR, estType = QUERY_BLOCK

Return code in qosdSetupDirCtx4QB: EXISTS

=====================================

SPD: END context at query block level

=====================================

Access path analysis for DYNTEST

***************************************

SINGLE TABLE ACCESS PATH

  Single Table Cardinality Estimation for DYNTEST[DYNTEST]

  SPD:#ff0000;"> Directive valid: dirid = 13237011096450186301, state = 1, flags = 1, #ff0000;">loc = 1 {EC(91171)[1, 2]}

  SPD: Return code in qosdDSDirSetup: EXISTS, estType = TABLE

  Column (#1): COUNTRY(VARCHAR2)

    AvgLen: 3 NDV: 4 Nulls: 0 Density: 0.250000

  Column (#2): WERKS(VARCHAR2)

    AvgLen: 5 NDV: 7 Nulls: 0 Density: 0.142857

 

  Table: DYNTEST  Alias: DYNTEST

    Card: Original: 7650.000000    >> #ff0000;">Single Tab Card adjusted from 273.214286 to 1000.000000 due to adaptive dynamic sampling

  Rounded: 1000  Computed: 1000.000000  Non Adjusted: 273.214286

  Scan IO  Cost (Disk) =   7.000000

  Scan CPU Cost (Disk) =   1462928.800000

  Total Scan IO  Cost  =   7.000000 (scan (Disk))

                         + 0.000000 (io filter eval) (= 0.000000 (per row) * 7650.000000 (#rows))

                       =   7.000000

  Total Scan CPU  Cost =   1462928.800000 (scan (Disk))

                         + 437142.857143 (cpu filter eval) (= 57.142857 (per row) * 7650.000000 (#rows))

                       =   1900071.657143

  Access Path: TableScan

    Cost:  7.058094  Resp: 7.058094  Degree: 0

      Cost_io: 7.000000  Cost_cpu: 1900072

      Resp_io: 7.000000  Resp_cpu: 1900072

  Best:: AccessPath: TableScan

         Cost: 7.058094  Degree: 1  Resp: 7.058094  Card: 1000.000000  Bytes: 0.000000

***************************************

 

I have highlighted the important SPD parts in red (some are duplicates in the trace file) - so let's have a closer look at these parts:

  • Hash table Object 91171 = Referenced data object id (e.g. referring to DBA_OBJECTS)
  • dirid = 13237011096450186301 = Used SQL Plan Directive (e.g. referring to DBA_SQL_PLAN_DIRECTIVES and DBA_SQL_PLAN_DIR_OBJECTS)
  • state = 1 = SQL Plan Directive internal state (e.g. 1 = NEW, 2 = MISSING_STATS, 3 = HAS_STATS as far as i could figure it out)
  • loc = 1 {EC(91171)[1, 2]} = Referenced/used columns of data object 91171 (e.g. referring to DBA_OBJECTS). It is important to note that these numbers "[1, 2]" are representing the column position in the table (not the SQL!). For example, the CBO trace content would look like this "loc = 1 {EC(91171)[2, 3]}", if you slightly change the table definition to "(TEXT VARCHAR(4000), COUNTRY VARCHAR2(40), WERKS VARCHAR(20)". The starting letters in the brackets "{}" describe the predicates in further detail (source Tweet by Franck Pachot):
    • E = Only equality predicates
    • C = Only simple column predicates
    • J = Index access by join predicates
    • F = Filter on joining object
  • Single Tab Card adjusted from 273.214286 to 1000.000000 due to adaptive dynamic sampling = I think this line is self-explanatory as it represents the adjusted cardinality based on dynamic sampling

 

So you can get most of the (used) SQL Plan Directive details for an already executed SQL by looking at the CBO trace. But some important information is missing, if you look closely. If you have ever done a cost based optimizer trace for/with dynamic sampling, you would normally expect something like this as well:

 

** Executed dynamic sampling query:

    level : 2

    sample pct. : 100.000000

    actual sample size : 7650

    filtered sample card. : 1000

    orig. card. : 1961

    block cnt. table stat. : 24

    block cnt. for sampling: 24

    max. sample block cnt. : 64

    sample block cnt. : 24

    min. sel. est. : 0.00010000

** Using dynamic sampling card. : 7650

** Dynamic sampling updated table card.

** Using single table dynamic sel. est. : 0.13071895

 

This is a common problem of all the "new" (adaptive) dynamic sampling methods (e.g. OPTIMIZER_DYNAMIC_SAMPLING = 11 / AUTO lacks this kind of information as well) and DBMS_SQLDIAG.DUMP_TRACE - it is not posted in the CBO trace file (by default). Luckily Oracle got a corresponding component called "SQL Dynamic Sampling Services (qksds)" in its kernel diagnostics + tracing infrastructure, that provides at least parts of this information.

 

SQL> oradebug doc component rdbms

Components in library RDBMS:

--------------------------

  SQL_DS               SQL Dynamic Sampling Services (qksds)

 

So let's rerun the the PL/SQL procedure DBMS_SQLDIAG.DUMP_TRACE with an additional trace option for SQL_DS.

 

SQL> alter session set events 'trace[RDBMS.SQL_DS] disk=high';

SQL> exec dbms_sqldiag.dump_trace('6jr7pwrk2tszg',0,'Optimizer','CBO_Optimizer_and_SQL_DS_Trace');

SPD: BEGIN context at statement level

=====================================

Stmt: ******* UNPARSED QUERY IS *******

SELECT "DYNTEST"."COUNTRY" "COUNTRY","DYNTEST"."WERKS" "WERKS","DYNTEST"."TEXT" "TEXT" FROM "TEST"."DYNTEST" "DYNTEST" WHERE "DYNTEST"."COUNTRY"='DE' AND "DYNTEST"."WERKS"='1200'

Objects referenced in the statement

  DYNTEST[DYNTEST] 91171, type = 1

Objects in the hash table

  Hash table Object 91171, type = 1, ownerid = 15196265155538183602:

    Dynamic Sampling Directives at location 1:

       dirid = 13237011096450186301, state = 2, flags = 1, loc = 1 {EC(91171)[1, 2]}

Return code in qosdInitDirCtx: ENBLD

===================================

SPD: END context at statement level

===================================

***************************************

BASE STATISTICAL INFORMATION

***********************

Table Stats::

  Table: DYNTEST  Alias: DYNTEST

  #Rows: 7650  SSZ: 0  LGR: 0  #Blks:  20  AvgRowLen:  13.00  NEB: 0  ChainCnt:  0.00  SPC: 0  RFL: 0  RNF: 0  CBK: 0  CHR: 0  KQDFLG: 1

  #IMCUs: 0  IMCRowCnt: 0  IMCJournalRowCnt: 0  #IMCBlocks: 0  IMCQuotient: 0.000000

=======================================

SPD: BEGIN context at query block level

=======================================

Query Block SEL$1 (#0)

Applicable DS directives:

   dirid = 13237011096450186301, state = 2, flags = 1, loc = 1 {EC(91171)[1, 2]}

Checking valid directives for the query block

  SPD: Return code in qosdDSDirSetup: NODIR, estType = QUERY_BLOCK

Return code in qosdSetupDirCtx4QB: EXISTS

=====================================

SPD: END context at query block level

=====================================

Access path analysis for DYNTEST

***************************************

SINGLE TABLE ACCESS PATH

  Single Table Cardinality Estimation for DYNTEST[DYNTEST]

  SPD: Directive valid: dirid = 13237011096450186301, state = 2, flags = 1, loc = 1 {EC(91171)[1, 2]}

  SPD: Return code in qosdDSDirSetup: EXISTS, estType = TABLE

  Column (#1): COUNTRY(VARCHAR2)

    AvgLen: 3 NDV: 4 Nulls: 0 Density: 0.250000

  Column (#2): WERKS(VARCHAR2)

    AvgLen: 5 NDV: 7 Nulls: 0 Density: 0.142857

 

  Table: DYNTEST  Alias: DYNTEST

    Card: Original: 7650.000000qksdsSInitCtx(): qksdsSInitCtx(): timeLimit(ms) = 2500

#ff0000; font-size: 8pt; font-family: courier new,courier;">qksdsCheckPreds():   qksdsCheckPreds(exit): total count=2 usable count=2

#ff0000; font-size: 8pt; font-family: courier new,courier;">qksdsExecute(): qksdsExecute(): enter

#ff0000; font-size: 8pt; font-family: courier new,courier;">qksdsInitSample(): do compute: nbSamp=2.5 totNbSamp=2.5 minIOs=100 maxIOs=18446744073709551615 nbBlocks=20 blockSize=8192 ioSize=8 tbName=DYNTEST

#ff0000; font-size: 8pt; font-family: courier new,courier;">qksdsExeStmt():   qksdsExeStmt(): enter

#ff0000; font-size: 8pt; font-family: courier new,courier;">qksdsExeStmt(): do compute: sampSize = 100

#ff0000; font-size: 8pt; font-family: courier new,courier;">qksdsExeStmt(): ************************************************************

#ff0000; font-size: 8pt; font-family: courier new,courier;">DS Query Text:

#ff0000; font-size: 8pt; font-family: courier new,courier;">SELECT /* DS_SVC */ /*+ dynamic_sampling(0) no_sql_tune no_monitoring optimizer_features_enable(default) no_parallel result_cache(snapshot=3600) */ SUM(C1) FROM (SELECT /*+ qb_name("innerQuery") NO_INDEX_FFS( "DYNTEST")  */ 1 AS C1 FROM "DYNTEST" "DYNTEST" WHERE ("DYNTEST"."WERKS"='1200') AND ("DYNTEST"."COUNTRY"='DE')) innerQuery

#ff0000; font-size: 8pt; font-family: courier new,courier;">qksdsExeStmt():

#ff0000; font-size: 8pt; font-family: courier new,courier;">qksdsExeStmt(): timeInt = 2 timeLimit = 2 elapTime = 0

#ff0000; font-size: 8pt; font-family: courier new,courier;">**************************************************************

#ff0000; font-size: 8pt; font-family: courier new,courier;">Iteration 1 

#ff0000; font-size: 8pt; font-family: courier new,courier;">  Exec count:         1

#ff0000; font-size: 8pt; font-family: courier new,courier;">  CR gets:            0

#ff0000; font-size: 8pt; font-family: courier new,courier;">  CU gets:            0

#ff0000; font-size: 8pt; font-family: courier new,courier;">  Disk Reads:         0

#ff0000; font-size: 8pt; font-family: courier new,courier;">  Disk Writes:        0

#ff0000; font-size: 8pt; font-family: courier new,courier;">  IO Read Requests:   0

#ff0000; font-size: 8pt; font-family: courier new,courier;">  IO Write Requests:  0

#ff0000; font-size: 8pt; font-family: courier new,courier;">  Bytes Read:         0

#ff0000; font-size: 8pt; font-family: courier new,courier;">  Bytes Written:      0

#ff0000; font-size: 8pt; font-family: courier new,courier;">  Bytes Exchanged with Storage:  0

#ff0000; font-size: 8pt; font-family: courier new,courier;">  Bytes Exchanged with Disk:  0

#ff0000; font-size: 8pt; font-family: courier new,courier;">  Bytes Simulated Read:  0

#ff0000; font-size: 8pt; font-family: courier new,courier;">  Bytes Simulated Returned:  0

#ff0000; font-size: 8pt; font-family: courier new,courier;">  Elapsed Time: 481 (us)

#ff0000; font-size: 8pt; font-family: courier new,courier;">  CPU Time: 480 (us)

#ff0000; font-size: 8pt; font-family: courier new,courier;">  User I/O Time: 0 (us)

#ff0000; font-size: 8pt; font-family: courier new,courier;">qksdsDumpEStats(): Sampling Input

#ff0000; font-size: 8pt; font-family: courier new,courier;">  IO Size:      8

#ff0000; font-size: 8pt; font-family: courier new,courier;">  Sample Size:  100.000000

#ff0000; font-size: 8pt; font-family: courier new,courier;">  Post S. Size: 100.000000

 

#ff0000; font-size: 8pt; font-family: courier new,courier;">qksdsExeStmt():   qksdsExeStmt: exit

#ff0000; font-size: 8pt; font-family: courier new,courier;">qksdsDumpStats(): **************************************************************

#ff0000; font-size: 8pt; font-family: courier new,courier;">DS Service Statistics

#ff0000; font-size: 8pt; font-family: courier new,courier;">qksdsDumpStats():   Executions:  1

#ff0000; font-size: 8pt; font-family: courier new,courier;">  Retries:     0

#ff0000; font-size: 8pt; font-family: courier new,courier;">  Timeouts:    0

#ff0000; font-size: 8pt; font-family: courier new,courier;">  ParseFails:  0

#ff0000; font-size: 8pt; font-family: courier new,courier;">  ExecFails:   0

#ff0000; font-size: 8pt; font-family: courier new,courier;">qksdsDumpStats(): qksdsDumpResult(): DS Results: #exps=1, smp obj=DYNTEST

#ff0000; font-size: 8pt; font-family: courier new,courier;">qksdsDumpResult():    T.CARD = qksdsDumpResult(): (mid=1000.0, low=1000.0, hig=1000.0)qksdsDumpResult():

#ff0000; font-size: 8pt; font-family: courier new,courier;">qksdsDumpResult(): end dumping resultsqksdsExecute(): qksdsExecute(): exit

    >> Single Tab Card adjusted from 273.214286 to 1000.000000 due to adaptive dynamic sampling

  Rounded: 1000  Computed: 1000.000000  Non Adjusted: 273.214286

  Scan IO  Cost (Disk) =   7.000000

  Scan CPU Cost (Disk) =   1462928.800000

  Total Scan IO  Cost  =   7.000000 (scan (Disk))

                         + 0.000000 (io filter eval) (= 0.000000 (per row) * 7650.000000 (#rows))

                       =   7.000000

  Total Scan CPU  Cost =   1462928.800000 (scan (Disk))

                         + 437142.857143 (cpu filter eval) (= 57.142857 (per row) * 7650.000000 (#rows))

                       =   1900071.657143

  Access Path: TableScan

    Cost:  7.058094  Resp: 7.058094  Degree: 0

      Cost_io: 7.000000  Cost_cpu: 1900072

      Resp_io: 7.000000  Resp_cpu: 1900072

  Best:: AccessPath: TableScan

         Cost: 7.058094  Degree: 1  Resp: 7.058094  Card: 1000.000000  Bytes: 0.000000

***************************************

 

There is no difference in the posted SQL Plan Directive information, but you get a lot of more details about the dynamic sampling itself (nearly the same amount of information as expected) instead of just a single line like "Single Tab Card adjusted from 273.214286 to 1000.000000 due to adaptive dynamic sampling".

 

 

Summary

I hope this short blog post about SQL Plan Directives provides you some more insights into the tracing possibilities and how you can get more details for an existing/loaded cursor.

If you have any further questions - please feel free to ask or get in contact directly, if you need assistance by troubleshooting Oracle database (performance) issues. You can also follow or drop me a note on Twitter of course.

 

 

References