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.
Hi Kerry,
what if SQL Plan Management is used in the database? May two different predicate sections occur within the same accepted plan?
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
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?
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
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?
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