[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’));
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’;
SQL> select * from DBA_SQL_PLAN_DIRECTIVES where DIRECTIVE_ID = 13237011096450186301;
SQL> select TYPE, STATUS, BUCKET_NO, HASH, NAME, CACHE_ID, CACHE_KEY from V$RESULT_CACHE_OBJECTS;
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
Hash table Object 91171, type = 1, ownerid = 15196265155538183602:
Dynamic Sampling Directives at location 1:
dirid = 13237011096450186301, state = 1, 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 = 1, 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 = 1, 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.000000 >> 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
qksdsCheckPreds(): qksdsCheckPreds(exit): total count=2 usable count=2
qksdsExecute(): qksdsExecute(): enter
qksdsInitSample(): do compute: nbSamp=2.5 totNbSamp=2.5 minIOs=100 maxIOs=18446744073709551615 nbBlocks=20 blockSize=8192 ioSize=8 tbName=DYNTEST
qksdsExeStmt(): qksdsExeStmt(): enter
qksdsExeStmt(): do compute: sampSize = 100
qksdsExeStmt(): ************************************************************
DS Query Text:
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
qksdsExeStmt():
qksdsExeStmt(): timeInt = 2 timeLimit = 2 elapTime = 0
**************************************************************
Iteration 1
Exec count: 1
CR gets: 0
CU gets: 0
Disk Reads: 0
Disk Writes: 0
IO Read Requests: 0
IO Write Requests: 0
Bytes Read: 0
Bytes Written: 0
Bytes Exchanged with Storage: 0
Bytes Exchanged with Disk: 0
Bytes Simulated Read: 0
Bytes Simulated Returned: 0
Elapsed Time: 481 (us)
CPU Time: 480 (us)
User I/O Time: 0 (us)
qksdsDumpEStats(): Sampling Input
IO Size: 8
Sample Size: 100.000000
Post S. Size: 100.000000
qksdsExeStmt(): qksdsExeStmt: exit
qksdsDumpStats(): **************************************************************
DS Service Statistics
qksdsDumpStats(): Executions: 1
Retries: 0
Timeouts: 0
ParseFails: 0
ExecFails: 0
qksdsDumpStats(): qksdsDumpResult(): DS Results: #exps=1, smp obj=DYNTEST
qksdsDumpResult(): T.CARD = qksdsDumpResult(): (mid=1000.0, low=1000.0, hig=1000.0)qksdsDumpResult():
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
- Frank Pachot – 12c SQL Plan Directive: state has changed between 12.1.0.1 and 12.1.0.2
- Frank Pachot – Matching SQL Plan Directives and extended stats
- Frank Pachot – Matching SQL Plan Directives and queries using it
- Frank Pachot – DBA_SQL_PLAN_DIRECTIVE.LAST_USED
- Frank Pachot – How to import SQL Plan Directives
- Frank Pachot – Tweet about internal states
- Tyler van Vierzen – Latch free waits, Dynamic Statistics, and the Result Cache
Wow Stefan,
you really became an Oracle internals expert blogger!
I am not aware of anybody else sharing that much detailed and hard engineered knowledge in the SAP@Oracle area.
We - I mean the whole SAP on Oracle Community - can be really happy to have you around!
Keep up the good work and thank you for all your effort!
- Lars
Lars,
thank you very much for the soft words. I try my best. I still have hope for you, that you will come back some day
By the way ... HAPPY BIRTHDAY to YOU! One more year to go to the 40 ... maybe a good anniversary to come back?
Regards
Stefan
Thanks Stefan... yep, the last year in 3x mode just started for me
But that's of course not the reason to go back to anything. Instead I am moving on (once again) and will leave the old world behind me soon.
Let's see to what extend DB-know how will help me with those large mice...