SQL Gone Bad – But Plan Not Changed? – Part 2

In Part 1 of this series I talked about the basic problem, which is that plan_hash_values are not based on the whole plan. One of the main missing components is the predicates associated with a plan, but there are other missing parts as was pointed out in Part 1 of Randolf Geist’s post on the topic. At any rate, predicates seem to be the most critical of the missing parts.

The purpose of this second post on the topic is to talk about diagnosis. Basically how do you identify when some other part of a plan has changed that doesn’t affect the plan_hash_value, specifically a predicate.

So first I thought I would show a few examples of statements with the same sql_id and plan_hash_value that have other plan differences (in the predicate section). To do this I used a method proposed by Randolf Geist a few years back in his 2nd post on the topic which covered Alternative Ways to Calculate a PLAN_HASH_VALUE In that post, Randolf shows several ways to compute a hash value on any or all of the columns in the v$sql_plan table. I wrote a simple script around one of the those methods (find_pred_mismatch.sql), and as you might guess from the name, I limited this version to not include all the columns in v$sql_plan, but to only identify statements with mismatched predicates. To be more explicit, the script will locate statements in the shared_pool that have multiple child cursors, where there are more than one set of predicates to go with a single plan_hash_value. Here’s an example:

SYS@DEMO1> @find_pred_mismatch
 
Type created.
 
 
SQL_ID        PLAN_HASH_VALUE CHILD_NUMBER   THE_HASH ARE_H
------------- --------------- ------------ ---------- -----
063m5s0cvrr19      1502175119            0 2709091620 DIFF!
093fgfvygm51m      3114044936            0 3689661040 DIFF!
0cn2wm9d7zq8d      1540383338            0 3746559344 DIFF!
0pt4jfmq9f1q0      3078496799            0 1309675335 DIFF!
155cwuv2pfp1d       768389713            0 2982291916 DIFF!
18c2yb5aj919t      1032442798            0 1714458756 DIFF!
1n9crga6mbw2x      4174841998            0 2752042257 DIFF!
1ytxrt5qp9qdd      2707146560            0 3757837347 DIFF!
23buxzfxyp1vy      3143617369            0 2089881285 DIFF!
23nad9x295gkf       891847141            0 4056778555 DIFF!
24zvjzuyrxh3w      1877711096            0 1680905434 DIFF!
28n17ru48jnh5      1665111388            0 3584687734 DIFF!
2j0fw19fph49j      1337823903            0 2431841938 DIFF!
2kd6nusgzc3uw      3151266570            0 3024843785 DIFF!
2rpwgryn7pxz5      3329544515            0  452505826 DIFF!
35nhk48nxwc0v      2553960494            0  117262982 DIFF!
3bc73t2h9mwxc      1420457580            0 1226225583 DIFF!
3gputsqv4u1j3      3161304745            0 2252819340 DIFF!
3zauy2zqryrsx      1420457580            0 1128973296 DIFF!
42q1qby3huf2c      3069437562            0 4008632079 DIFF!
47mm81hm9sggy      1836210496            0 1554180227 DIFF!
4g46czps3t55u      2714703948            0 4063401817 DIFF!
4n2gca427719q      1360319091            0 4013571180 DIFF!
4tpsnbkt1dm5j      2960949352            0 3341004783 DIFF!
5dyhfnkzta2zm      3767331201            0 4238766232 DIFF!
5h91zx386wbht       293199272            0  949799344 DIFF!
5s34t44u10q4g      2693539438            0  839739072 DIFF!
5uw1u291s3m0k       219265157            0  642280427 DIFF!
61tn3mam0vq0b      2012170170            0 2048362545 DIFF!
63t3ufgq37m0c      1155609947            0  844291465 DIFF!
69k5bhm12sz98      3091659676            0  356777601 DIFF!
6cp74g22fzahf        76968983            0 1617454724 DIFF!
6wm3n4d7bnddg      1772758172            0 1148123313 DIFF!
78kp0fcyxavzb      2960949352            0 1085639264 DIFF!
7ah4afrggrw5c      4213028598            0 4285032606 DIFF!
7g4rxwbvhdh3q      3170022080            0 2083442940 DIFF!
7hspvruktu52b      4016032974            0 2538340188 DIFF!
84p3g5b5bsfvn       681044650            0 3826083810 DIFF!
86521pa77y28j      3760090177            0 3887843475 DIFF!
8ak9gkw2mjhvr      1526940012            0 2946674232 DIFF!
8p9z2ztb272bm       408663731            0 3293625021 DIFF!
aca4xvmz0rzup       427901911            0 4215668999 DIFF!
akh9zqqkx3wj7      2306922995            0 2084689096 DIFF!
akx4284f2vjnv      3948068913            0 2662025793 DIFF!
amycufzt6uq5f      3283312188            0 1896511712 DIFF!
atnkqhrp3t7xa      2196914545            0   26873046 DIFF!
aw2x7hh2a9ag0      1148557212            0  719001678 DIFF!
b41wak2bb7atw       108532975            0 1699960507 DIFF!
bhvyz9bgyrhb2      1134671139            0 2402404248 DIFF!
c8gnrhxma4tas      4024720576            0 2473084105 DIFF!
cc7vvmrsxzyq1      1849127868            0 1912933403 DIFF!
cjtaqp92v10bn       922118807            0 2313573387 DIFF!
ckfgcyv05xptf      2869192503            0 3932622422 DIFF!
cw860p03hy5ff      1502175119            0 2915988156 DIFF!
cyw0c6qyrvsdd       192117504            0 2551186960 DIFF!
d53nc7j6n1057      1356236608            0  582788179 DIFF!
dyj1ssw8jw54f      1836210496            0   66902761 DIFF!
fkjkrv5ycz96u      2247257083            0 1809299677 DIFF!
gdn3ysuyssf82      4024720576            0 2473084105 DIFF!
gwbdd5m45ugpm      3180770434            0  235716193 DIFF!
 
60 rows selected.
 
SYS@DEMO1> select * from table(dbms_xplan.display_cursor('&sql_id','&child_no','typical'));
Enter value for sql_id: 24zvjzuyrxh3w
Enter value for child_no: 
 
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  24zvjzuyrxh3w, child number 0
-------------------------------------
SELECT script FROM sys.metaxsl$ WHERE xmltag=:1 AND transform=:2  AND
model=:3
 
Plan hash value: 1877711096
 
--------------------------------------------------------------------------------------
| Id  | Operation                 | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT          |          |       |       |     3 (100)|          |
|*  1 |  TABLE ACCESS STORAGE FULL| METAXSL$ |     3 |    99 |     3   (0)| 00:00:01 |
--------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   1 - storage(("XMLTAG"=:1 AND "TRANSFORM"=:2 AND "MODEL"=:3))
       filter(("XMLTAG"=:1 AND "TRANSFORM"=:2 AND "MODEL"=:3))
 
SQL_ID  24zvjzuyrxh3w, child number 1
-------------------------------------
SELECT script FROM sys.metaxsl$ WHERE xmltag=:1 AND transform=:2  AND
model=:3
 
Plan hash value: 1877711096
 
----------------------------------------------
| Id  | Operation                 | Name     |
----------------------------------------------
|   0 | SELECT STATEMENT          |          |
|*  1 |  TABLE ACCESS STORAGE FULL| METAXSL$ |
----------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   1 - storage(("MODEL"=:3 AND "TRANSFORM"=:2 AND "XMLTAG"=:1))
       filter(("MODEL"=:3 AND "TRANSFORM"=:2 AND "XMLTAG"=:1))
 
Note
-----
   - rule based optimizer used (consider using cbo)
 
 
44 rows selected.

So as you can see, even on my little test DB with very little activity, there are a number of statements that have multiple cursors with predicates that don’t match. And it’s easy to see the differences in the predicates section if there are only a handful of predicates. But when you have a big complex statement it can become much more difficult to do it manually. But that’s what SQL is for and fortunately, Carlos Sierra has already done most of the work for us. See his post on Identifying Which Predicates Don’t Match. Of course I usually can’t leave well enough alone so I modified one of his diff scripts slightly (diff_predicates.sql). Here’s an example of it’s usage.

 
SYS@DEMO1> -- first XPLAN output for a statement with mismatched predicates
SYS@DEMO1>
SYS@DEMO1> select * from table(dbms_xplan.display_cursor('&sql_id','&child_no','typical'));
Enter value for sql_id: gwbdd5m45ugpm
Enter value for child_no: 
 
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  gwbdd5m45ugpm, child number 0
-------------------------------------
 SELECT startsn.sga_size_factor * 100 as factor,
startsn.sga_size as start_size_mb,         endsn.sga_size as
end_size_mb,      (endsn.estd_db_time - startsn.estd_db_time) * 1000000
as dbtime,         0 as version_changed  FROM  WRH$_SGA_TARGET_ADVICE
startsn ,  WRH$_SGA_TARGET_ADVICE endsn  WHERE  startsn.dbid
  =  :dbid    AND  startsn.snap_id           =  :begin_snap_id    AND
startsn.instance_number   =  :inst_num    AND  startsn.sga_size_factor
>= 1    AND  endsn.dbid                = startsn.dbid    AND
endsn.snap_id             =  :end_snap_id    AND  endsn.instance_number
    = startsn.instance_number    AND  endsn.sga_size_factor     =
startsn.sga_size_factor  ORDER BY startsn.sga_size_factor ASC
 
Plan hash value: 755415579
 
-------------------------------------------------------------------------------------------------------------------
| Id  | Operation                             | Name                      | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                      |                           |       |       |     8 (100)|          |
|   1 |  SORT ORDER BY                        |                           |     9 |   486 |     8   (0)| 00:00:01 |
|*  2 |   HASH JOIN                           |                           |     9 |   486 |     8   (0)| 00:00:01 |
|*  3 |    TABLE ACCESS BY INDEX ROWID BATCHED| WRH$_SGA_TARGET_ADVICE    |     9 |   243 |     4   (0)| 00:00:01 |
|*  4 |     INDEX RANGE SCAN                  | WRH$_SGA_TARGET_ADVICE_PK |    14 |       |     2   (0)| 00:00:01 |
|*  5 |    TABLE ACCESS BY INDEX ROWID BATCHED| WRH$_SGA_TARGET_ADVICE    |     9 |   243 |     4   (0)| 00:00:01 |
|*  6 |     INDEX RANGE SCAN                  | WRH$_SGA_TARGET_ADVICE_PK |    14 |       |     2   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   2 - access("ENDSN"."DBID"="STARTSN"."DBID" AND "ENDSN"."INSTANCE_NUMBER"="STARTSN"."INSTANCE_NUMBER"
              AND "ENDSN"."SGA_SIZE_FACTOR"="STARTSN"."SGA_SIZE_FACTOR")
   3 - filter("STARTSN"."SGA_SIZE_FACTOR">=1)
   4 - access("STARTSN"."DBID"=TO_NUMBER(:DBID) AND "STARTSN"."SNAP_ID"=TO_NUMBER(:BEGIN_SNAP_ID) AND
              "STARTSN"."INSTANCE_NUMBER"=TO_NUMBER(:INST_NUM))
   5 - filter("ENDSN"."SGA_SIZE_FACTOR">=1)
   6 - access("ENDSN"."DBID"=TO_NUMBER(:DBID) AND "ENDSN"."SNAP_ID"=TO_NUMBER(:END_SNAP_ID) AND
              "ENDSN"."INSTANCE_NUMBER"=TO_NUMBER(:INST_NUM))
 
SQL_ID  gwbdd5m45ugpm, child number 1
-------------------------------------
 SELECT startsn.sga_size_factor * 100 as factor,
startsn.sga_size as start_size_mb,         endsn.sga_size as
end_size_mb,      (endsn.estd_db_time - startsn.estd_db_time) * 1000000
as dbtime,         0 as version_changed  FROM  WRH$_SGA_TARGET_ADVICE
startsn ,  WRH$_SGA_TARGET_ADVICE endsn  WHERE  startsn.dbid
  =  :dbid    AND  startsn.snap_id           =  :begin_snap_id    AND
startsn.instance_number   =  :inst_num    AND  startsn.sga_size_factor
>= 1    AND  endsn.dbid                = startsn.dbid    AND
endsn.snap_id             =  :end_snap_id    AND  endsn.instance_number
    = startsn.instance_number    AND  endsn.sga_size_factor     =
startsn.sga_size_factor  ORDER BY startsn.sga_size_factor ASC
 
Plan hash value: 755415579
 
-------------------------------------------------------------------------------------------------------------------
| Id  | Operation                             | Name                      | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                      |                           |       |       |     8 (100)|          |
|   1 |  SORT ORDER BY                        |                           |     9 |   486 |     8   (0)| 00:00:01 |
|*  2 |   HASH JOIN                           |                           |     9 |   486 |     8   (0)| 00:00:01 |
|*  3 |    TABLE ACCESS BY INDEX ROWID BATCHED| WRH$_SGA_TARGET_ADVICE    |     9 |   243 |     4   (0)| 00:00:01 |
|*  4 |     INDEX RANGE SCAN                  | WRH$_SGA_TARGET_ADVICE_PK |    14 |       |     2   (0)| 00:00:01 |
|*  5 |    TABLE ACCESS BY INDEX ROWID BATCHED| WRH$_SGA_TARGET_ADVICE    |     9 |   243 |     4   (0)| 00:00:01 |
|*  6 |     INDEX RANGE SCAN                  | WRH$_SGA_TARGET_ADVICE_PK |    14 |       |     2   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   2 - access("ENDSN"."DBID"="STARTSN"."DBID" AND "ENDSN"."INSTANCE_NUMBER"="STARTSN"."INSTANCE_NUMBER"
              AND "ENDSN"."SGA_SIZE_FACTOR"="STARTSN"."SGA_SIZE_FACTOR")
   3 - filter("STARTSN"."SGA_SIZE_FACTOR">=1)
   4 - access("STARTSN"."DBID"=:DBID AND "STARTSN"."SNAP_ID"=:BEGIN_SNAP_ID AND
              "STARTSN"."INSTANCE_NUMBER"=:INST_NUM)
   5 - filter("ENDSN"."SGA_SIZE_FACTOR">=1)
   6 - access("ENDSN"."DBID"=:DBID AND "ENDSN"."SNAP_ID"=:END_SNAP_ID AND
              "ENDSN"."INSTANCE_NUMBER"=:INST_NUM)
 
 
80 rows selected.
 
SYS@DEMO1> -- not too easy to find the differences is it?
SYS@DEMO1> -- even on a relatively short plan
SYS@DEMO1>
SYS@DEMO1> @diff_predicates
Enter value for sql_id: gwbdd5m45ugpm
 
SQL_ID               PHV   CHILD_NO         ID ACCESS_PREDICATES                        FILTER_PREDICATES
------------- ---------- ---------- ---------- ---------------------------------------- ----------------------------------------
gwbdd5m45ugpm  755415579          0          4 "STARTSN"."DBID"=TO_NUMBER(:DBID) AND
                                               "STARTSN"."SNAP_ID"=TO_NUMBER(:BEGIN_SNA
                                               P_ID) AND
                                               "STARTSN"."INSTANCE_NUMBER"=TO_NUMBER(:I
                                               NST_NUM)
 
               755415579          1          4 "STARTSN"."DBID"=:DBID AND
                                               "STARTSN"."SNAP_ID"=:BEGIN_SNAP_ID AND
                                               "STARTSN"."INSTANCE_NUMBER"=:INST_NUM
 
               755415579          0          6 "ENDSN"."DBID"=TO_NUMBER(:DBID) AND
                                               "ENDSN"."SNAP_ID"=TO_NUMBER(:END_SNAP_ID
                                               ) AND
                                               "ENDSN"."INSTANCE_NUMBER"=TO_NUMBER(:INS
                                               T_NUM)
 
               755415579          1          6 "ENDSN"."DBID"=:DBID AND
                                               "ENDSN"."SNAP_ID"=:END_SNAP_ID AND
                                               "ENDSN"."INSTANCE_NUMBER"=:INST_NUM

All that’s cool, but what about the situation where your statement worked fine historically but doesn’t work now. No problem, just look at the predicates that AWR stores in DBA_HIST_SQL_PLAN right? Well there is bad news on that front, because AWR doesn’t store predicate information. There are actually a couple of bugs logged on MOS for that since 10g.

Bug 5217053 : IN DBA_HIST_SQL_PLAN SOME FIELDS ARE NOT GETTING POPULATED
Bug 7493519 : ACCESS_PREDICATES AND FILTER_PREDICATES MISSING IN DBA_SQL_PLAN_HIST

So I thought that maybe I could use the old Statspack routines (the predecessor to AWR) to capture the predicates, but alas, Statspack doesn’t capture them either. Oddly enough it sticks a value of 0 in the fields that should hold the predicates. And in fact, there is also a bug listed for Statspack since version 9i.

Bug 5683955 : ACCESS AND FILTER PREDICATE NOT POPULATED STATS$SQL_PLAN

But there is some good news. Good old Statspack still ships with 11g and the source code is exposed! So it is easy to change it to capture the predicates. So I did just that. Here’s a copy of the modified spcpkg.sql script that re-creates the statspack package: (kso_spcpkg.sql) And here’s a little output to show how it can be used. (note that your snaps must be at level 6 or higher to get plan info)

PERFSTAT@dbm1> !cp /u01/app/oracle/product/11.2.0.2/dbhome_1/rdbms/admin/spcpkg.sql kso_spcpkg.sql
 
-- here's the statement I changed
 
            insert into stats$sql_plan
                 ( plan_hash_value
                 , id
                 , operation
                 , options
                 , object_node
                 , object#
                 , object_owner
                 , object_name
                 , object_alias
                 , object_type
                 , optimizer
                 , parent_id
                 , depth
                 , position
                 , search_columns
                 , cost
                 , cardinality
                 , bytes
                 , other_tag
                 , partition_start
                 , partition_stop
                 , partition_id
                 , other
                 , distribution
                 , cpu_cost
                 , io_cost
                 , temp_space
                 , access_predicates
                 , filter_predicates
                 , projection
                 , time
                 , qblock_name
                 , remarks
                 , snap_id
                 )
            select /*+ ordered use_nl(s) use_nl(sp.p) */
                   new_plan.plan_hash_value
                 , sp.id
                 , max(sp.operation)
                 , max(sp.options)
                 , max(sp.object_node)
                 , max(sp.object#)
                 , max(sp.object_owner)
                 , max(sp.object_name)
                 , max(sp.object_alias)
                 , max(sp.object_type)
                 , max(sp.optimizer)
                 , max(sp.parent_id)
                 , max(sp.depth)
                 , max(sp.position)
                 , max(sp.search_columns)
                 , max(sp.cost)
                 , max(sp.cardinality)
                 , max(sp.bytes)
                 , max(sp.other_tag)
                 , max(sp.partition_start)
                 , max(sp.partition_stop)
                 , max(sp.partition_id)
                 , max(sp.other)
                 , max(sp.distribution)
                 , max(sp.cpu_cost)
                 , max(sp.io_cost)
                 , max(sp.temp_space)
                 , 0 -- should be max(sp.access_predicates) (2254299)
                 , 0 -- should be max(sp.filter_predicates)
                 , max(sp.projection)
                 , max(sp.time)
                 , max(sp.qblock_name)
                 , max(sp.remarks)
                 , max(new_plan.snap_id)
              from (select /*+ index(spu) */
                           spu.plan_hash_value
                         , spu.hash_value    hash_value
                         , spu.address       address
                         , spu.text_subset   text_subset
                         , spu.snap_id       snap_id
                      from stats$sql_plan_usage spu
                     where spu.snap_id         = l_snap_id
                       and spu.dbid            = p_dbid
                       and spu.instance_number = p_instance_number
                       and not exists (select /*+ nl_aj */ *
                                         from stats$sql_plan ssp
                                        where ssp.plan_hash_value
                                            = spu.plan_hash_value
                                      )
                   )          new_plan
                 , v$sql      s      -- join reqd to filter already known plans
                 , v$sql_plan sp
             where s.address         = new_plan.address
               and s.plan_hash_value = new_plan.plan_hash_value
               and s.hash_value      = new_plan.hash_value
               and sp.hash_value     = new_plan.hash_value
               and sp.address        = new_plan.address
               and sp.hash_value     = s.hash_value
               and sp.address        = s.address
               and sp.child_number   = s.child_number
             group by
                   new_plan.plan_hash_value, sp.id
             order by
                   new_plan.plan_hash_value, sp.id; -- deadlock avoidance
 
-- and here's what I changed it to 
 
            insert into stats$sql_plan
                 ( plan_hash_value
                 , id
                 , operation
                 , options
                 , object_node
                 , object#
                 , object_owner
                 , object_name
                 , object_alias
                 , object_type
                 , optimizer
                 , parent_id
                 , depth
                 , position
                 , search_columns
                 , cost
                 , cardinality
                 , bytes
                 , other_tag
                 , partition_start
                 , partition_stop
                 , partition_id
                 , other
                 , distribution
                 , cpu_cost
                 , io_cost
                 , temp_space
                 , access_predicates
                 , filter_predicates
                 , projection
                 , time
                 , qblock_name
                 , remarks
                 , snap_id
                 )
            select /*+ ordered use_nl(s) use_nl(sp.p) */
                   new_plan.plan_hash_value
                 , sp.id
                 , max(sp.operation)
                 , max(sp.options)
                 , max(sp.object_node)
                 , max(sp.object#)
                 , max(sp.object_owner)
                 , max(sp.object_name)
                 , max(sp.object_alias)
                 , max(sp.object_type)
                 , max(sp.optimizer)
                 , max(sp.parent_id)
                 , max(sp.depth)
                 , max(sp.position)
                 , max(sp.search_columns)
                 , max(sp.cost)
                 , max(sp.cardinality)
                 , max(sp.bytes)
                 , max(sp.other_tag)
                 , max(sp.partition_start)
                 , max(sp.partition_stop)
                 , max(sp.partition_id)
                 , max(sp.other)
                 , max(sp.distribution)
                 , max(sp.cpu_cost)
                 , max(sp.io_cost)
                 , max(sp.temp_space)
                 , max(sp.access_predicates)
                 , max(sp.filter_predicates)
                 , max(sp.projection)
                 , max(sp.time)
                 , max(sp.qblock_name)
                 , max(sp.remarks)
                 , max(new_plan.snap_id)
              from (select /*+ index(spu) */
                           spu.plan_hash_value
                         , spu.hash_value    hash_value
                         , spu.address       address
                         , spu.text_subset   text_subset
                         , spu.snap_id       snap_id
                      from stats$sql_plan_usage spu
                     where spu.snap_id         = l_snap_id
                       and spu.dbid            = p_dbid
                       and spu.instance_number = p_instance_number
                       and not exists (select /*+ nl_aj */ *
                                         from stats$sql_plan ssp
                                        where ssp.plan_hash_value
                                            = spu.plan_hash_value
                                      )
                   )          new_plan
                 , v$sql      s      -- join reqd to filter already known plans
                 , v$sql_plan sp
             where s.address         = new_plan.address
               and s.plan_hash_value = new_plan.plan_hash_value
               and s.hash_value      = new_plan.hash_value
               and sp.hash_value     = new_plan.hash_value
               and sp.address        = new_plan.address
               and sp.hash_value     = s.hash_value
               and sp.address        = s.address
               and sp.child_number   = s.child_number
             group by
                   new_plan.plan_hash_value, sp.id
             order by
                   new_plan.plan_hash_value, sp.id; -- deadlock avoidance
 
PERFSTAT@dbm1> @kso_spcpkg.sql
Creating Package STATSPACK...
 
Package created.
 
No errors.
Creating Package Body STATSPACK...
 
Package body created.
 
No errors.
 
NOTE:
SPCPKG complete. Please check spcpkg.lis for any errors.
 
PERFSTAT@dbm1> exec statspack.snap(i_snap_level => 6, i_modify_parameter => 'true');
 
PL/SQL procedure successfully completed.
 
PERFSTAT@dbm1> select distinct snap_id from perfstat.stats$sql_summary;
 
   SNAP_ID
----------
         1
         2
         3
 
PERFSTAT@dbm1> select distinct sql_id from perfstat.stats$sql_summary where rownum < 10;
 
SQL_ID
-------------
bn4b3vjw2mj3u
bkryyh4vf4p55
bxywuzvtp6wjg
b2hrmq9xsdw51
b62q7nc33gzwx
c3hhngpbpvvmk
c7rzm2g7qsy7c
cbdfcfcp1pgtp
byaarkxm6b0r1
 
9 rows selected.
 
PERFSTAT@dbm1> select * from table(dbms_xplan.display_cursor('&sql_id','&child_no','typical'));
Enter value for sql_id: byaarkxm6b0r1
Enter value for child_no: 0
 
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  byaarkxm6b0r1, child number 0
-------------------------------------
SELECT /*+ use_nl(u,o,t) */ NVL(T.DEGREE,1) FROM USER$ U,OBJ$ O,TAB$ T
WHERE U.NAME=:B2 AND O.NAME=:B1 AND O.OBJ#=T.OBJ# AND U.USER#=O.OWNER#
 
Plan hash value: 3095026863
 
-----------------------------------------------------------------------------------------
| Id  | Operation                     | Name    | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |         |       |       |     3 (100)|          |
|   1 |  NESTED LOOPS                 |         |     1 |    52 |     3   (0)| 00:00:01 |
|   2 |   NESTED LOOPS                |         |     1 |    45 |     2   (0)| 00:00:01 |
|   3 |    TABLE ACCESS BY INDEX ROWID| USER$   |     1 |    17 |     1   (0)| 00:00:01 |
|*  4 |     INDEX UNIQUE SCAN         | I_USER1 |     1 |       |     0   (0)|          |
|*  5 |    INDEX RANGE SCAN           | I_OBJ2  |     1 |    28 |     1   (0)| 00:00:01 |
|   6 |   TABLE ACCESS CLUSTER        | TAB$    |     1 |     7 |     1   (0)| 00:00:01 |
|*  7 |    INDEX UNIQUE SCAN          | I_OBJ#  |     1 |       |     0   (0)|          |
-----------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   4 - access("U"."NAME"=:B2)
   5 - access("U"."USER#"="O"."OWNER#" AND "O"."NAME"=:B1)
   7 - access("O"."OBJ#"="T"."OBJ#")
 
PERFSTAT@dbm1> -- now let's see what's in the statspack table
PERFSTAT@dbm1>
PERFSTAT@dbm1> select '    '||id||' - access('||access_predicates||')' Predicates
  2  from perfstat.stats$sql_plan
  3  where plan_hash_value = 3095026863
  4  and access_predicates is not null;
 
PREDICATES
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
    4 - access("U"."NAME"=:B2)
    5 - access("U"."USER#"="O"."OWNER#" AND "O"."NAME"=:B1 AND "O"."TYPE#"=2)
    7 - access("O"."OBJ#"="T"."OBJ#")

So you can see Statspack does collect predicates after this modification. I’ve talked to a couple of people who have had repeated multiple occurrences of this issue. So if you’re in that camp, it might be worthwhile to do something like this.

Keep in mind though that this simple fix is not perfect. Notice that the predicates in my example don’t match exactly what I got when I used XPLAN to spit out the plan information. That’s because the cursor that I picked for the XPLAN call had a different set of predicates than the one that was captured by Statspack. You see, the design for both Statspack and AWR uses plan_hash_value as the key and so there will be only one plan (and one set of predicates) stored per plan_hash_value. That’s probably not so bad if you are trying to figure out why a plan went bad after running well for some time. But as you can see in the example above, it can be confusing. I don’t know for sure, but I suspect that’s why the developers have not fixed the fact that predicates are not stored in Statspack and AWR, even though they are clearly aware of the issue (ala the bugs in MOS and the comments in the statspack script). But you have the source, so if you want to modify it to store all predicates you could certainly do that (please let me know if you do).

Of course then you’d want a script to compare what’s in Statspack with what’s in the shared pool (let me know if you write that one too). :)

So that’s it for now. I intend to do a third post on this topic and discuss some ideas on how to control the performance instability issues resulting from changing predicates. Hopefully I can get to that soon. As always, your comments are welcome.

6 Comments

  1. Wojciech says:

    Hi Kerry,

    what if SQL Plan Management is used in the database? May two different predicate sections occur within the same accepted plan?

  2. osborne says:

    Hi Wojciech,

    Great question. Part 3 of this series will be about how one might control the issue, but the short answer is no, baselines won’t solve the problem. The underlying issue is that plan_hash_value is calculated without the predicates, and that’s the basis for what SPM is trying to accomplish (i.e. keeping the plan_hash_value the same). So I’m sorry to say that they are not currently designed to control predicates (even in 12c).

    Kerry

  3. max says:

    Hi Kerry,

    Great stuff as usual, but i had a question(maybe i need to read this post again, as i might not have understand it) but when you run your script(find_pred_mismatch) you said “the script will locate statements in the shared_pool that have multiple child cursors”…. as we are already assuming a new child has been created…would you guess that something might have changed there(maybe new bind data or something else)….

    for example. the SQI_ID you gave 24zvjzuyrxh3w had 2 child(0 and 1)…and one would know right away(maybe) something is different as oracle created a new child….how would one diagnose one sqlid and only one child…. we are facing a similar situtaion where that sql has been running fine for last couple of months(takes about 2000 secs) and last week it went to 14000 seconds….when we check plan was the same, no new child was created, LIO and PIO are pertty much the same…so it got me thinking about your blogs as i had read this in the past….and re-read it again…any idea how would you out if something similar is happening if SQLID and child# are the same?

  4. osborne says:

    Hi Max,

    It’s possible that earlier version of the statement has aged out of the cursor cache and then when it is re-parsed it ends up as child 0 with the same plan_hash_value but the predicates are different. In this case you could try testing with various bind values and see if you can reproduce the issue. But it is difficult at best. The problem is that AWR doesn’t store predicate info so you can’t really go back to check. You might try saving off the predicate info from the bad version before flushing the cursor (or whatever you do to resolve the issue) and then comparing to the predicate info when you get the good plan back. The scripts in this post may be able to help with the compare as visual comparison can be difficult. Sorry that I can’t help more but this is a difficult issue to resolve.

    Kerry

  5. max says:

    Kerry, Thanks for your reply. i later figured out why it ran longer…look at DB time activity and compared it to last 2 weeks and the workload was almost 10X more than normal due to something loading we were not aware and it happened exactly what the SQL statment was run and that made it suffered more….

    Also is it safe to assume that you will have multiple child# if you run into the situation that you talked about(predicates being wrongly ordered) or that would not be the case?

  6. osborne says:

    Hi Max,

    Glad to hear you figured out what was happening.. To answer your question, you may or may not see multiple child cursors. If a statement is run infrequently it may be aged out of the cursor cache between executions which means you could have a situation where there are different performance characteristics due to the predicate mismatch, but there would be no way to identify it unless you had captured the predicates yourself some where along the way. So there’s little you can do to verify what’s happen if you are doing forensics and there is only one child in the shared pool.

    Kerry

Leave a Reply