Profiling Execution Plans

In my previous blog post, I demonstrated how to identify the active lines in an adaptive execution plan on DBA_HIST_SQL_PLAN so that I could profile behaviour. This post demonstrates a practical application of that technique. This statement comes out of the PeopleSoft Financials Multi-currency Processing. A process extracts groups of rows in elimination sets into a working storage table and joins that table to the ledger table for further processing. The number of rows extracted from the elimination set selector table (PS_ELIM_CF_SEL2001 in this case) can vary in a single process from a few to a few thousand. However, the process does regather optimizer statistics each time.

SQL_ID fwcdxjy41j23n
--------------------
SELECT L.BUSINESS_UNIT,L.ACCOUNT,L.DEPTID,L.PRODUCT,L.BUDGET_REF,L.AFFIL
IATE,L.CHARTFIELD1,L.BOOK_CODE,L.GL_ADJUST_TYPE,L.DATE_CODE,SUM(L.POSTED
_TOTAL_AMT) FROM PS_ELIM_CF_SEL2001 S, PS_LEDGER L WHERE
S.ELIMINATION_SET='UK_OTHER' AND S.TREE_NODE_NUM=1234567890 AND
S.PROCESS_INSTANCE=0001234567 AND L.FISCAL_YEAR=2018 AND
L.LEDGER=S.LEDGER AND L.BUSINESS_UNIT=S.BUSINESS_UNIT AND
L.AFFILIATE=S.AFFILIATE AND L.ACCOUNT=S.ACCOUNT AND L.CURRENCY_CD='GBP'
AND L.STATISTICS_CODE=' ' AND (L.ACCOUNTING_PERIOD<=001 AND
((L.ACCOUNTING_PERIOD>=0 AND S.BALANCE_FWD_SW='Y') OR
L.ACCOUNTING_PERIOD>=1 AND S.BALANCE_FWD_SW='N')) GROUP BY
L.BUSINESS_UNIT,L.ACCOUNT,L.DEPTID,L.PRODUCT,L.BUDGET_REF,L.AFFILIATE,L.
CHARTFIELD1,L.BOOK_CODE,L.GL_ADJUST_TYPE,L.DATE_CODE

The changing literal values mean that every SQL statement has a different SQL_ID. SQL Baselines are not viable here. No one plan produces optimal performance, so a traditional SQL profile proscribing a particular plan is not the answer. Oracle moves between three adaptive plans depending at least partially upon the number of rows in the elimination table.

Plan hash value: 42743070
-----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                              | Name               | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
-----------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                       |                    |       |       |   237K(100)|       |          |       |
|   1 |  SORT GROUP BY                         |                    |    13 |  1716 |   237K  (1)| 00:00:10 |       |       |
|-  2 |   HASH JOIN                            |                    |    13 |  1716 |   237K  (1)| 00:00:10 |       |       |
|   3 |    NESTED LOOPS                        |                    |    13 |  1716 |   237K  (1)| 00:00:10 |       |       |
|-  4 |     STATISTICS COLLECTOR               |                    |       |       |            |       |          |       |
|   5 |      TABLE ACCESS STORAGE FULL         | PS_ELIM_CF_SEL2001 |    13 |   728 |   138   (2)| 00:00:01 |       |       |
|   6 |     PARTITION RANGE OR                 |                    |     1 |    76 | 18249   (1)| 00:00:01 |KEY(OR)|KEY(OR)|
|   7 |      PARTITION LIST ITERATOR           |                    |     1 |    76 | 18249   (1)| 00:00:01 |   KEY |   KEY |
|   8 |       TABLE ACCESS BY LOCAL INDEX ROWID| PS_LEDGER          |     1 |    76 | 18249   (1)| 00:00:01 |   KEY |   KEY |
|   9 |        INDEX RANGE SCAN                | PSCLEDGER          |     1 |       | 18228   (1)| 00:00:01 |   KEY |   KEY |
|- 10 |    PARTITION RANGE OR                  |                    |     1 |    76 | 18249   (1)| 00:00:01 |KEY(OR)|KEY(OR)|
|- 11 |     PARTITION LIST JOIN-FILTER         |                    |     1 |    76 | 18249   (1)| 00:00:01 |:BF0000|:BF0000|
|- 12 |      TABLE ACCESS STORAGE FULL         | PS_LEDGER          |     1 |    76 | 18249   (1)| 00:00:01 |   KEY |   KEY |
-----------------------------------------------------------------------------------------------------------------------------

Plan hash value: 3968216348
-----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                              | Name               | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
-----------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                       |                    |       |       |  1679K(100)|       |          |       |
|   1 |  SORT GROUP BY                         |                    |    92 | 12236 |  1679K  (1)| 00:01:06 |       |       |
|   2 |   HASH JOIN                            |                    |    92 | 12236 |  1679K  (1)| 00:01:06 |       |       |
|-  3 |    NESTED LOOPS                        |                    |    92 | 12236 |  1679K  (1)| 00:01:06 |       |       |
|-  4 |     STATISTICS COLLECTOR               |                    |       |       |            |       |          |       |
|   5 |      TABLE ACCESS STORAGE FULL         | PS_ELIM_CF_SEL2001 |    92 |  5244 |   138   (2)| 00:00:01 |       |       |
|-  6 |     PARTITION RANGE OR                 |                    |     1 |    76 | 18249   (1)| 00:00:01 |KEY(OR)|KEY(OR)|
|-  7 |      PARTITION LIST ITERATOR           |                    |     1 |    76 | 18249   (1)| 00:00:01 |   KEY |   KEY |
|-  8 |       TABLE ACCESS BY LOCAL INDEX ROWID| PS_LEDGER          |     1 |    76 | 18249   (1)| 00:00:01 |   KEY |   KEY |
|-  9 |        INDEX RANGE SCAN                | PSCLEDGER          |     1 |       | 18228   (1)| 00:00:01 |   KEY |   KEY |
|  10 |    PARTITION RANGE OR                  |                    |     1 |    76 | 18249   (1)| 00:00:01 |KEY(OR)|KEY(OR)|
|  11 |     PARTITION LIST JOIN-FILTER         |                    |     1 |    76 | 18249   (1)| 00:00:01 |:BF0000|:BF0000|
|  12 |      TABLE ACCESS STORAGE FULL         | PS_LEDGER          |     1 |    76 | 18249   (1)| 00:00:01 |   KEY |   KEY |
-----------------------------------------------------------------------------------------------------------------------------

Plan hash value: 386495123
------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                               | Name               | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                        |                    |       |       |  1763K(100)|       |          |       |
|   1 |  SORT GROUP BY                          |                    |     1 |   132 |  1763K  (2)| 00:01:09 |       |       |
|   2 |   HASH JOIN                             |                    |  2105 |   271K|  1763K  (2)| 00:01:09 |       |       |
|   3 |    PART JOIN FILTER CREATE              | :BF0000            |  2105 |   271K|  1763K  (2)| 00:01:09 |       |       |
|-  4 |     NESTED LOOPS                        |                    |  2105 |   271K|  1763K  (2)| 00:01:09 |       |       |
|-  5 |      STATISTICS COLLECTOR               |                    |       |       |            |       |          |       |
|   6 |       TABLE ACCESS STORAGE FULL         | PS_ELIM_CF_SEL2001 |  2113 |   115K|   138   (2)| 00:00:01 |       |       |
|-  7 |      PARTITION RANGE OR                 |                    |     1 |    76 |  1763K  (2)| 00:01:09 |KEY(OR)|KEY(OR)|
|-  8 |       PARTITION LIST ITERATOR           |                    |     1 |    76 |  1763K  (2)| 00:01:09 |   KEY |   KEY |
|-  9 |        TABLE ACCESS BY LOCAL INDEX ROWID| PS_LEDGER          |     1 |    76 |  1763K  (2)| 00:01:09 |   KEY |   KEY |
|- 10 |         INDEX RANGE SCAN                | PSCLEDGER          |       |       |            |       |      KEY |   KEY |
|  11 |    PARTITION RANGE OR                   |                    |    24M|  1743M|  1763K  (2)| 00:01:09 |KEY(OR)|KEY(OR)|
|  12 |     PARTITION LIST JOIN-FILTER          |                    |    24M|  1743M|  1763K  (2)| 00:01:09 |:BF0000|:BF0000|
|  13 |      TABLE ACCESS STORAGE FULL          | PS_LEDGER          |    24M|  1743M|  1763K  (2)| 00:01:09 |   KEY |   KEY |
------------------------------------------------------------------------------------------------------------------------------

Only a small proportion of statements run by the process are captured during AWR snapshots. With PeopleSoft, because there is so much dynamically generated non-sharable SQL, I generally recommend reducing the snapshot interval to 15 minutes and collecting the top 100 statements (the default is hourly and the top 30 statements), and even so we only have a limited number of samples with the larger statements more likely to be sampled.
We are already using SQL Profiles to apply optimizer parameters to this statement so I can identify entries in DBA_HIST_SQLSTAT by the matched profile, though I could also use the FORCE_MATCHING_SIGNATURE. I will start by extracting the SQL statistics for all matching statements into a temporary working storage table, including the OTHER_XML from the SQL Plan

drop table my_stats purge;
create table my_stats as 
with s as (
 select s.dbid, s.sql_id, s.plan_hash_value, s.sql_profile, s.action
 ,      max(s.optimizer_cost) optimizer_cost
 ,      max(s.PX_SERVERS_EXECS_DELTA) px_servers
 ,      sum(ELAPSED_TIME_DELTA)/1e6 elapsed_time
 from   dba_hist_snapshot x
 ,      dba_hist_sqlstat s
 WHERE  s.SNAP_id = X.SNAP_id
 AND    s.dbid = x.dbid
 AND    s.instance_number = x.instance_number
 AND    s.module = 'GLPOCONS'
 and    s.sql_profile LIKE 'GLPOCONS_AD%B2%'
 and    s.plan_hash_value > 0
 group by s.dbid, s.sql_id, s.plan_hash_value, s.sql_profile, s.action
)
SELECT s.*
,      xmltype(other_xml) other_xml
FROM   s, dba_hist_sql_plan p
WHERE  p.dbid = s.dbid
and    p.sql_id = s.sql_id
and    p.plan_hash_value = s.plan_hash_value
and    p.other_xml IS NOT NULL
and    p.id = 1
/
select count(*) from my_stats 
/

I found it was necessary to break this up into two stages.  Otherwise, I got ORA-32036: unsupported case for inlining of query name in WITH clause. This could be a manifestation of Bug 19684504 - ORA-32036 executing WITH statement with XML (Doc ID 19684504.8)

set pages 99 long 10
break on sql_profile skip 1
column sql_profile     format a17
column op              format 999
column dis             format 999
column par             format 999
column dep             format 999
column skp             format 999
column plan_hash_value format 9999999999 heading 'PHV'
column px_servers      format 9999       heading 'PX|Serv'
column ecost           format 9999       heading 'Elim|Cost'
column lcost           format 99999999   heading 'Ledger|Cost'
column ecard           format 99999      heading 'Elim|Card'
column lcard           format 99999999   heading 'Ledger|Card'
column optimizer_cost  format 99999999   heading 'Opt|Cost'
column elapsed_time    format 9999.99    heading 'Elapsed|Time'
column object_name     format a18 
column elim_obj        format a7         heading 'Bloom?' 
column epoptions       format a14        heading 'Join|Options'
column epoperation     format a16        heading 'Join|Operation'
column eoptions        format a14        heading 'Elim|Options'
column loptions        format a20        heading 'Ledger|Options'
column options         format a20
spool dmk
with y as (
select /*+MATERIALIZE*/ x.*
,      xt.*
,      p.object_type, p.object_name
,      p.operation, p.options, p.cost, p.cardinality
from   my_stats x
,      xmltable('/other_xml/display_map/row' PASSING x.other_xml
       COLUMNS "OP" NUMBER path '@op',
               "DIS" NUMBER path '@dis',
               "PAR" NUMBER path '@par',
               "DEP" NUMBER path '@dep',
               "SKP" NUMBER path '@skp'
       ) xt
,      dba_hist_sql_plan p
where  xt.skp = 0
and    p.dbid = x.dbid
and    p.sql_id = x.sql_id
and    p.plan_hash_Value = x.plan_hash_value
and    p.id = xt.op
)
select x.sql_profile, x.sql_id, x.plan_hash_value, x.px_servers
,      e.object_name, e.options eoptions, e.cardinality ecard, e.cost ecost
,      l.options loptions, l.cardinality lcard, l.cost lcost
,      ep.operation epoperation, ep.object_name elim_obj
,      x.optimizer_cost, x.elapsed_time
From   my_stats x
,      y e
,      y l
,      y ep
WHERE  e.dbid = x.dbid
And    e.sql_id = x.sql_id
And    e.plan_hash_Value = x.plan_hash_value
And    e.object_name like 'PS_ELIM_CF_SEL%'
And    e.object_type = 'TABLE'
AND    l.dbid = x.dbid
And    l.sql_id = x.sql_id
And    l.plan_hash_Value = x.plan_hash_value
And    l.object_name = 'PS_LEDGER'
And    l.object_type = 'TABLE'
And    ep.dbid = x.dbid
And    ep.sql_id = x.sql_id
And    ep.plan_hash_Value = x.plan_hash_value
And    ep.dis = e.par /*parent of display line*/
ORDER by x.sql_profile, e.cardinality, x.optimizer_cost, x.elapsed_time
/
spool off

The SQL query to profile the plan will be different for each set of plans that I want to investigate. The query showing in this blog was developed for the plan I am investigating here. I am interested in three aspects of the execution plan, the access method for each of the two tables, and the method by which they are joined. So, I have to join each SQL stats sub-query (X) back to the execution plan sub-query (Y) three times, selecting a different row from the plan each time.

• E: table access of PS_ELIM_CF_SEL% table, either by a FULL scan or it might be by ROWID if an index was used.
• L: table access of PS_LEDGER table. This will either be a FULL scan or by ROWID if an index was used.
• EP: parent of table access of PS_ELIM_CF_SEL%. This will either be a HASH JOIN or the creation of the Bloom Filter (:BF000). If I order the result by the cardinality of the PS_ELIM_CF_SEL% I can see how and when the plan changes as the number of rows retrieved from it (the cardinality) change.

                                               PX                    Elim             Elim  Elim Ledger                  Ledger    Ledger Join                           Opt Elapsed
SQL_PROFILE       SQL_ID                PHV  Serv OBJECT_NAME        Options          Card  Cost Options                   Card      Cost Operation        Bloom?       Cost    Time
----------------- ------------- ----------- ----- ------------------ -------------- ------ ----- -------------------- --------- --------- ---------------- ------- --------- -------
GLPOCONS_ADPB2001 b7hy0jfppdvn2    42743070     0 PS_ELIM_CF_SEL2001 STORAGE FULL      13   138 BY LOCAL INDEX ROWID         1     18249 NESTED LOOPS                237379      .40
…
                  9yz896xyn5aky    42743070     0 PS_ELIM_CF_SEL2001 STORAGE FULL      51   138 BY LOCAL INDEX ROWID         1     18249 NESTED LOOPS                930851     2.62
                  cbnz1jumm0x23    42743070     0 PS_ELIM_CF_SEL2001 STORAGE FULL      52   138 BY LOCAL INDEX ROWID         1     18249 NESTED LOOPS                949101      .66
…
                  cmajgmuyc3hc3    42743070     0 PS_ELIM_CF_SEL2001 STORAGE FULL      92   138 BY LOCAL INDEX ROWID         1     18249 NESTED LOOPS               1679071    21.89
                  3sbkyfwy6xk02  3968216348     0 PS_ELIM_CF_SEL2001 STORAGE FULL      92   138 STORAGE FULL                 1     18249 HASH JOIN                  1679071    51.95
                  27pxj6qu49zzr  3968216348     0 PS_ELIM_CF_SEL2001 STORAGE FULL      92   138 STORAGE FULL                 1     18249 HASH JOIN                  1679071    52.49
                  8nfbzan3hbzdg  3968216348     0 PS_ELIM_CF_SEL2001 STORAGE FULL      92   138 STORAGE FULL                 1     18249 HASH JOIN                  1679071    67.49
                  827sykfucq01t  3968216348     0 PS_ELIM_CF_SEL2001 STORAGE FULL      93   138 STORAGE FULL                 1     18249 HASH JOIN                  1697321    87.65
                  fmd3r4848nypk  3968216348     0 PS_ELIM_CF_SEL2001 STORAGE FULL      93   138 STORAGE FULL                 1     18249 HASH JOIN                  1697321    89.39
                  34h7j9rqf8y73  2660510816     0 PS_ELIM_CF_SEL2001 STORAGE FULL      97   138 BY LOCAL INDEX ROWID         1   1763685 NESTED LOOPS               1763970     1.54
                  0cfqyuz79qd09   386495123     0 PS_ELIM_CF_SEL2001 STORAGE FULL      98   138 STORAGE FULL          24054654   1763685 PART JOIN FILTER :BF0000   1763970    21.32
                  ff5hf8zpwhmd2   386495123     0 PS_ELIM_CF_SEL2001 STORAGE FULL      98   138 STORAGE FULL          24054654   1763685 PART JOIN FILTER :BF0000   1763970    26.64
                  9j0m5gq5aqssz   386495123     0 PS_ELIM_CF_SEL2001 STORAGE FULL      99   138 STORAGE FULL          24054654   1763685 PART JOIN FILTER :BF0000   1763970    34.28
                  bzbqrc7bw768q    42743070     0 PS_ELIM_CF_SEL2001 STORAGE FULL     102   138 BY LOCAL INDEX ROWID         1     18249 NESTED LOOPS               1861564      .76
                  bjjx0fxmtqzzt    42743070     0 PS_ELIM_CF_SEL2001 STORAGE FULL     102   138 BY LOCAL INDEX ROWID         1     18249 NESTED LOOPS               1861564     3.66
                  aqcxt7par2a22  2660510816     0 PS_ELIM_CF_SEL2001 STORAGE FULL     104   138 BY LOCAL INDEX ROWID         1   1763685 NESTED LOOPS               1763970     9.57
                  4cfsq52xzftpz   386495123     0 PS_ELIM_CF_SEL2001 STORAGE FULL     104   138 STORAGE FULL          24054654   1763685 PART JOIN FILTER :BF0000   1763970    25.39
                  76hq9zbfrm599   386495123     0 PS_ELIM_CF_SEL2001 STORAGE FULL     104   138 STORAGE FULL          24054654   1763685 PART JOIN FILTER :BF0000   1763970    26.11
                  2b8ck8kpyrvhg   386495123     0 PS_ELIM_CF_SEL2001 STORAGE FULL     104   138 STORAGE FULL          24054654   1763685 PART JOIN FILTER :BF0000   1763970    35.71
                  6gtu9tauhp55y   386495123     0 PS_ELIM_CF_SEL2001 STORAGE FULL     104   138 STORAGE FULL          24054654   1763685 PART JOIN FILTER :BF0000   1763970    39.77
…
                  88kyxqx2qbjxg   386495123     0 PS_ELIM_CF_SEL2001 STORAGE FULL    1021   138 STORAGE FULL          24054654   1763685 PART JOIN FILTER :BF0000   1763970    21.73
…
                  dh39mtw8rga5s   386495123     0 PS_ELIM_CF_SEL2001 STORAGE FULL    2113   138 STORAGE FULL          24054654   1763685 PART JOIN FILTER :BF0000   1763970    40.26

I can see that the optimizer goes backwards and forwards between different plans at different times as the cardinality increases. Nevertheless, I can make some informed decisions about how to adjust the optimizer parameters for this statement with hints introduced by a SQL Profile.

• I can change the point where the optimizer switches from to the full scan and bloom filter to a lower cardinality by increasing the cost of the index with a higher value optimizer_index_cost_adj.
• I can enable automatic parallelism with parallel_degree_policy, scale the calculated degree of parallelism with parallel_degree_level, but limit the degree of parallelism with parallel_degree_limit. The threshold for parallelism can be set with parallel_min_time_threshold. The parallelism threshold can be set at a slightly lower cardinality than the switch to the full scan.
• The settings can be tested using EXPLAIN PLAN FOR with the cardinality hint to set the number of rows returned from the PS_ELIM_CF_SEL% table

explain plan for
SELECT /*+cardinality(s 300)
NO_EXPAND 
OPT_PARAM('parallel_degree_policy','AUTO')
OPT_PARAM('parallel_min_time_threshold',220)
OPT_PARAM('parallel_degree_limit',40)
OPT_PARAM('optimizer_index_cost_adj',10912)
*/
L.BUSINESS_UNIT,L.ACCOUNT,L.DEPTID,L.PRODUCT,L.BUDGET_REF
…
/
set echo off trimspool on pages 999 lines 200 autotrace off
select * from table(dbms_xplan.display(null,null,'ADVANCED +ADAPTIVE -PROJECTION -PREDICATE -OUTLINE'));

When satisfactory values have been determined, they can be passed back into the SQL Profile.

…
h := SYS.SQLPROF_ATTR(
q'[BEGIN_OUTLINE_DATA]',
q'[OPT_PARAM('parallel_degree_policy','AUTO')]',
q'[OPT_PARAM('parallel_min_time_threshold',60)]',
q'[OPT_PARAM('parallel_degree_limit',40)]',
q'[OPT_PARAM('optimizer_index_cost_adj',10912)]',
q'[NO_EXPAND]',
…
q'[END_OUTLINE_DATA]');
…
DBMS_SQLTUNE.IMPORT_SQL_PROFILE (
sql_text    => sql_txt,
profile     => h,
name        => 'GLPOCONS_'||i.id,
…
replace     => TRUE,
force_match => TRUE /* TRUE:FORCE (match even when different literals in SQL). FALSE:EXACT (similar to CURSOR_SHARING) */ 
);
…