Different sql id, different force matching signature, different rows processed with the same plan hash value

Very recently, two interesting blog articles, here and here, have been published to emphasize the possibility of having a same plan hash value for actually two different execution plans.

Since then, I started opening my eyes for any plan hash value that is shown for two or more execution plans. That’s way, the last week, when I was modeling an example for an outer join in response to a question that came up in the French forum, I was immediately attracted by the following sql I have engineered:

SQL> select
2             d.deptno
3            ,d.dname
4            ,e.hiredate
5      from
6            dept d, emp e
7      where
8            d.deptno = e.deptno(+)
9      AND EXISTS
10                 ( SELECT  NULL
11                   FROM    emp e2
12                   WHERE   e.deptno    = e2.deptno
13                   HAVING  MAX(e2.hiredate) = e.hiredate
14                  -- or e.hiredate is null
15                   )
16       ;

DEPTNO DNAME      HIREDATE
------ ---------- ---------
20    RESEARCH    12/01/83
30    SALES       03/12/81
10    ACCOUNTING  23/01/82

Plan hash value: 2339135578  --> note this plan hash value

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------
| Id  | Operation            | Name | Starts | E-Rows | A-Rows |   A-Time   |
-----------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |      |      1 |        |      3 |00:00:00.01 |
|*  1 |  FILTER              |      |      1 |        |      3 |00:00:00.01 |
|*  2 |   HASH JOIN OUTER    |      |      1 |     14 |     15 |00:00:00.01 |
|   3 |    TABLE ACCESS FULL | DEPT |      1 |      4 |      4 |00:00:00.01 |
|   4 |    TABLE ACCESS FULL | EMP  |      1 |     14 |     14 |00:00:00.01 |
|*  5 |   FILTER             |      |     15 |        |      3 |00:00:00.01 |
|   6 |    SORT AGGREGATE    |      |     15 |      1 |     15 |00:00:00.01 |
|*  7 |     TABLE ACCESS FULL| EMP  |     15 |      5 |     70 |00:00:00.01 |
-----------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter( IS NOT NULL)
2 - access("D"."DEPTNO"="E"."DEPTNO")
5 - filter(MAX("E2"."HIREDATE")=:B1) --> note this crucial point here
7 - filter("E2"."DEPTNO"=:B1)

And to this a little bit different sql:

SQL> select
2             d.deptno
3            ,d.dname
4            ,e.hiredate
5      from
6            dept d, emp e
7      where
8            d.deptno = e.deptno(+)
9      AND EXISTS
10            ( SELECT  NULL
11              FROM    emp e2
12              WHERE   e.deptno    = e2.deptno
13              HAVING  MAX(e2.hiredate) = e.hiredate
14              or e.hiredate is null  --> this part has been uncommented
15             )
16       ;

DEPTNO DNAME          HIREDATE
---------- -------------- --------
20 RESEARCH       12/01/83
30 SALES          03/12/81
10 ACCOUNTING     23/01/82
40 OPERATIONS

Plan hash value: 2339135578  --> the same plan hash value
-----------------------------------------------------------------------------
| Id  | Operation            | Name | Starts | E-Rows | A-Rows |   A-Time   |
-----------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |      |      1 |        |      4 |00:00:00.01 |
|*  1 |  FILTER              |      |      1 |        |      4 |00:00:00.01 |
|*  2 |   HASH JOIN OUTER    |      |      1 |     14 |     15 |00:00:00.01 |
|   3 |    TABLE ACCESS FULL | DEPT |      1 |      4 |      4 |00:00:00.01 |
|   4 |    TABLE ACCESS FULL | EMP  |      1 |     14 |     14 |00:00:00.01 |
|*  5 |   FILTER             |      |     15 |        |      4 |00:00:00.01 |
|   6 |    SORT AGGREGATE    |      |     15 |      1 |     15 |00:00:00.01 |
|*  7 |     TABLE ACCESS FULL| EMP  |     15 |      5 |     70 |00:00:00.01 |
-----------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter( IS NOT NULL)
2 - access("D"."DEPTNO"="E"."DEPTNO")
5 - filter((MAX("E2"."HIREDATE")=:B1 OR :B2 IS NULL)) --> for a different predicate
7 - filter("E2"."DEPTNO"=:B1)

Well, nothing new per regard to the two related blog articles mentioned above.  However it is worth pointing out how two different sql_id with two different force matching signature and producing two different result sets, could end up sharing the same plan hash value of two execution plans differencing by their predicate part as shown below:

select
  sql_id
 ,child_number
 ,force_matching_signature
 ,rows_processed
 ,plan_hash_value
from
v$sql
where sql_text like '%MAX(e2.hiredate)%'
and   sql_text not like '%v$sql%';

SQL_ID        CHILD_NUMBER FORCE_MATCHING_SIGNATURE ROWS_PROCESSED PLAN_HASH_VALUE
------------- ------------ ------------------------ -------------- ---------------
ba39fv7txcsbk            0 6256287308517838235              4      2339135578
b2kggnvz02ctk            0 1563627505656661161              3      2339135578

In this context of plan hash value inspection, Carlos sierra from the Oracle support published a blog article showing that his sqltxplain tool has the ability to consider execution plan using not only the plan hash value but two additional pieces of information which are SQLT Plan Hash Value1 and SQLT Plan Hash Value2. The last information is related to the predicate part which is here the central point of difference between “my” two execution plans.

Well, why not try sqltxtract for this case using sql_id ba39fv7txcsbk (click on the picture to enlarge it)?

Spot how the sqltxtract module shows the presence of two execution plans having the same plan hash value (2339135578) but different plan hash value2(62199 and 22135). This plan hash value2 concerns a difference into the access and/or the filter predicates.

But wait, this doesn’t mean that the sql_id ba39fv7txcsbk has necessarily got two different execution plans. All what it clearly indicates is that the plan hash value of this parent sql_id has been seen two times, each time with a different access and/or filter predicates. This is confirmed by the sql scripts given by Carlos sierra which when applied to this particular case gives this:

SQL> start c:\psql_id
Enter value for sql_id: ba39fv7txcsbk

no rows selected

Meaning that this sql_id has not got a difference in the predicate part of its execution plan.

SQL> start c:\phash

Enter value for plan_hash_value: 2339135578

ID  TYPE     SQL_ID         CHILD_NUMBER  PREDICATES
---- -------- -------------- ------------- ------------------------------------------
5   filter  ba39fv7txcsbk    0             (MAX("E2"."HIREDATE")=:B1 OR :B2 IS NULL)
5   filter  b2kggnvz02ctk    0              MAX("E2"."HIREDATE")=:B1

Meaning that this plan_hash_value has got two execution plans having two different predicate parts for two different sql_ids

ORA-08102: index key not found: Part II

Last year I wrote a note about how I succeeded to overcome an index key not found error by moving the underlying table not without mentioning that an offline rebuild of the corrupted index reveals to be of no help.  Because, in contrast to an online index rebuild which is based on the table data, an offline index rebuild is based on the index data. And, as far as this data is corrupted in the index, rebuilding the same index with the same data will  produce the same error.

What prompted me to write this article is that, yesterday,  we have been confronted to the same error with the same index in the ACCEPTANCE (beta) database.

I was going to play with this case by tracing(10046 events) an offline rebuild first and then set the index in an unusable state before rebuilding  it offline when I received an e-mail from a DBA telling that he has successfully rebuilt the culprit index online. Too late.

Fortunately, yes you read it correctly, the day after, the same error occurred again but this time on another index of the same table.

The occasion was then given to me again to check the suggestion made by Jason Bucata (see comment 2) about putting the index in an unusable state and rebuild it offline. As such, i.e. when index is in an unusable state, even if this index is rebuilt offline, Oracle will use the underlying table to reconstruct the corrupted index in contrast to a “valid” index rebuilt offline where the underlying table is not used during this kind of rebuild.

And by the way, instead of rebuilding the newly corrupted index, I decide to consider all the table indexes (it is not very safe  but I could not take a risk of another day with a new different corrupted index)

select 'alter index ' ||index_name || ' unusable;' from user_indexes where table_name = 'TABLE_XXX';
select 'alter index ' ||index_name || ' rebuild;'  from user_indexes where table_name = 'TABLE_XXX';

The 10046 trace for the rebuild offline of an unusable index identified by its object_id (obj#=245082) belonging to a table identified by its object_id ( obj#=244832) when tkprofed show this:

alter index XXX_IND_NI rebuild

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       75      0.32       0.37          0         96          0           0
Execute      1    182.96     174.86     492687     368598      75682           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       76    183.28     175.23     492687     368694      75682           0

Misses in library cache during parse: 75
Optimizer mode: ALL_ROWS
Parsing user id: 47

Elapsed times include waiting on following events:

Event waited on                             Times   Max. Wait  Total Waited
----------------------------------------   Waited  ----------  ------------
SQL*Net break/reset to client                 150        0.00          0.17
SQL*Net message to client                      76        0.00          0.00
SQL*Net message from client                    76      146.07        169.65
db file scattered read                       6588        0.61          7.27
db file sequential read                       821        0.03          0.08
direct path write temp                        320        0.29          5.81
direct path read temp                        4498        0.06          1.17
log file sync                                   2        0.02          0.02
log file switch completion                      8        0.31          0.73
direct path write                               6        0.00          0.00
reliable message                                1        0.00          0.00
enq: RO - fast object reuse                     1        0.00          0.00
rdbms ipc reply                                 1        0.01          0.01
********************************************************************************

The presence of db file scattered read wait event is a clear indication of a full segment read; and their high number (6588) compared to the db file sequential read (821) suggests that this offline rebuild (of an unusable index) has been done using the underlying table.

Note, by the way, the unusual high number (47) of Misses in Library cache during parse and a cpu time (183 seconds) greater than the elapsed time (175 seconds)

The trace file shows also the following interesting information:

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

PARSING IN CURSOR #2 len=43 dep=0 uid=47 oct=9 lid=47 tim=22486851823983 hv=2687996766 ad='920eda48'
alter index XXX_IND_NI rebuild
END OF STMT

PARSE #2:c=10000,e=6576,p=0,cr=9,cu=0,mis=1,r=0,dep=0,og=1,tim=22486851823977
BINDS #2:
WAIT #2: nam='db file scattered read' ela= 2526 file#=37 block#=21 blocks=58 obj#=244832 tim=22486851828916
WAIT #2: nam='db file scattered read' ela= 4839 file#=37 block#=79 blocks=58 obj#=244832 tim=22486851838736
WAIT #2: nam='db file scattered read' ela= 3139 file#=37 block#=137 blocks=58 obj#=244832 tim=22486851847085
WAIT #2: nam='db file scattered read' ela= 2603 file#=37 block#=195 blocks=58 obj#=244832 tim=22486851853977
WAIT #2: nam='db file scattered read' ela= 5218 file#=37 block#=253 blocks=58 obj#=244832 tim=22486851863154
WAIT #2: nam='db file scattered read' ela= 2313 file#=37 block#=311 blocks=58 obj#=244832 tim=22486851868008
WAIT #2: nam='db file scattered read' ela= 2611 file#=37 block#=369 blocks=58 obj#=244832 tim=22486851875983
WAIT #2: nam='db file scattered read' ela= 3098 file#=37 block#=427 blocks=58 obj#=244832 tim=22486851882593
WAIT #2: nam='db file scattered read' ela= 3194 file#=37 block#=485 blocks=58 obj#=244832 tim=22486851892313
WAIT #2: nam='db file scattered read' ela= 2763 file#=37 block#=543 blocks=58 obj#=244832 tim=22486851901798
WAIT #2: nam='db file scattered read' ela= 3374 file#=37 block#=601 blocks=48 obj#=244832 tim=22486851912129
WAIT #2: nam='db file scattered read' ela= 3214 file#=37 block#=1299 blocks=58 obj#=244832 tim=22486851918241
WAIT #2: nam='db file scattered read' ela= 3015 file#=37 block#=1357 blocks=58 obj#=244832 tim=22486851927379
WAIT #2: nam='db file scattered read' ela= 2787 file#=37 block#=1415 blocks=58 obj#=244832 tim=22486851936055
………..

WAIT #2: nam='db file sequential read' ela= 79 file#=45 block#=3152 blocks=1 obj#=244832 tim=22486853368773
WAIT #2: nam='db file scattered read' ela= 365 file#=45 block#=3154 blocks=55 obj#=244832 tim=22486853369742
WAIT #2: nam='db file scattered read' ela= 464 file#=45 block#=3852 blocks=58 obj#=244832 tim=22486853373874
WAIT #2: nam='db file scattered read' ela= 680 file#=45 block#=3910 blocks=58 obj#=244832 tim=22486853378189
WAIT #2: nam='db file scattered read' ela= 1957 file#=45 block#=3968 blocks=58 obj#=244832 tim=22486853385193
WAIT #2: nam='db file scattered read' ela= 846 file#=45 block#=4026 blocks=58 obj#=244832 tim=22486853390273
WAIT #2: nam='db file scattered read' ela= 456 file#=45 block#=4084 blocks=58 obj#=244832 tim=22486853395209
WAIT #2: nam='db file scattered read' ela= 455 file#=45 block#=4142 blocks=58 obj#=244832 tim=22486853399969
etc….

A very high number of db file scattered read on obj#=244832 which represents the object id of the table to which is attached to corrupted index.

Finally, the bottom line from this blog article is to show that when an index is corrupted (ora-08102) it is possible to rebuild it offline but you should first set it into an unusable state.

SQLTXPLAIN: Execution plan and operation order : Exec Ord column

I’ve recently decided to start exploring the Oracle SQLTXPLAIN tool developed by Carlos Sierra from Oracle support. Up to know I am still exploring the different possibilities that tool offers for diagnosing query response time performance problem. I thought that the best strategy to start with SQLTXPLAIN is to take a query that I have trouble shouted using a traditional method and apply SQLTXTRACT for it to see if I can point out from this SQLTXTRACT output the issue I know it is at the origin of the query performance problem.

While I was exploring the execution plan part of the sqltxtract report applied to my query

ID	Exec Ord	Operation	Go To	More	Cost2	Estim Card
0	8	SELECT STATEMENT			255	100
1	7	NESTED LOOPS		[+]	257
2	5	. NESTED LOOPS		[+]	254	100
3	3	.. SORT UNIQUE		[+]	103	100
4	2	… TABLE ACCESS BY INDEX ROWID T2	[+]	[+]	103	100
5	1	…. INDEX RANGE SCAN T2_I1	[+]	[+]	3	100
6	4	.. INDEX RANGE SCAN T1_N1	[+]	[+]	2	1
7	6	. TABLE ACCESS BY INDEX ROWID T1	[+]	[+]	3	1

I was suddenly attracted by the Exec Ord column. That’s a very nice feature showing the order of the operation as they have been executed by the SQL engine. However, the traditional strategy for reading plans following a parent-child relationship and indentation is not always correct.  This is why I decided to see if the Exec Ord column is correctly reported in the particular cases where the traditional plan reading is wrong. For that I used the example given by Jonathan Lewis in his “constant subquery” case and that you can easily reproduce:

------------------------------------------------------------------
| Id  | Operation             | Name  | Starts | E-Rows | A-Rows |
------------------------------------------------------------------
|*  1 |  FILTER               |       |      1 |        |      0 |
|*  2 |   HASH JOIN RIGHT SEMI|       |      0 |      1 |      0 |
|   3 |    TABLE ACCESS FULL  | F1    |      0 |     20 |      0 |
|   4 |    TABLE ACCESS FULL  | T1    |      0 |  10000 |      0 |
|*  5 |   INDEX UNIQUE SCAN   | F2_PK |      1 |      1 |      0 |
------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter( IS NOT NULL)
2 - access("F1"."ID"="T1"."ID" AND "F1"."SMALL_VC"="T1"."SMALL_VC")
5 - access("F2"."ID"=21)

The traditional plan reading will say that the first operation started here is operation 3, followed by operation 4 all combined with operation 2; and finally the operation 5 is triggered by its parent operation 1. But, as explained in Jonathan Lewis post, things have not been executed as this traditional plan reading suggests. Operation 2, 3 and 4 has not been started at all (Starts = 0).

My curiosity dictated me to run sqltxtract for the above query and get the corresponding execution plan together with the Exec Ord column:

ID	Exec Ord	Operation	Go To	More	Cost2	Estim Card	Work Area
0	6	SELECT STATEMENT			55
1	5	FILTER		[+]	55
2	3	. HASH JOIN RIGHT SEMI		[+]	55	1	[+]
3	1	.. TABLE ACCESS FULL F1	[+]	[+]	3	20
4	2	.. TABLE ACCESS FULL T1	[+]	[+]	51	10000
5	4	. INDEX UNIQUE SCAN F2_PK	[+]	[+]	0	1

As you can see from the above execution plan, sqltxtract module is, unfortunately, also reporting a wrong operation order (Exec Ord column) as far as it is showing that the first operations executed here are operation 3 and 4 while actually these two operations have not been executed at all. It would be very nice if the Exec Ord operation could take into account the special cases where the traditional “first child first” rule is not applicable. Among those cases, I know two :  the  “constant subquery” and index scan with a filter predicate applying a subquery