Online Statistics Gathering

Online Statistics Gathering, https://sqlmaria.com/2017/01/03/online-statistics-gathering/, is a pretty cool feature for the ages-old version that is Oracle 12.1, especially data warehouses.

As a recap, when you do direct path load into an empty segment, Oracle will take advantage of gathering statistics on the data whilst it is loading it, i.e no need to go back and re-read in an explicit stats gathering.

Note that, per Maria’s note, only base table and column statistics are gathered, not histograms but those can be gathered without re-gathering base column statistics via GATHER AUTO.

Old news.

We have only recently upgraded a complex application from 11.2.0.4 and hit an issue which is really obvious in hindsight but just worth pointing out, particular in combination with another feature?

I’m sure the behaviour below will come as no surprise in 11.2.0.4

drop table t1;
create global temporary table t1
on commit preserve rows
as
select * from user_objects where rownum <= 100;

explain plan for
select * from t1;

select * from table(dbms_xplan.display);
select num_rows from user_tables where table_name = 'T1';
select column_name, num_nulls, num_distinct from user_tab_columns where table_name = 'T1';

The output of note:

Plan hash value: 3617692013
----------------------------------------------------------------------------------
| Id | Operation                      | Name | Rows | Bytes | Cost (%CPU)| Time  |
----------------------------------------------------------------------------------
|  0 | SELECT STATEMENT               |      |  100 | 19000 |   2  (0)| 00:00:01 |
|  1 | TABLE ACCESS STORAGE FULL      | T1   |  100 | 19000 |   2  (0)| 00:00:01 |
----------------------------------------------------------------------------------

Note
-----
  - dynamic sampling used for this statement (level=2)


 NUM_ROWS
----------
      

COLUMN_NAME           NUM_NULLS NUM_DISTINCT
-------------------- ---------- ------------
GENERATED                       
SECONDARY                       
NAMESPACE                       
EDITION_NAME                      
OBJECT_NAME                      
SUBOBJECT_NAME                     
OBJECT_ID                       
DATA_OBJECT_ID                     
OBJECT_TYPE                      
CREATED                        
LAST_DDL_TIME                     
TIMESTAMP                       
STATUS                         
TEMPORARY                       
                 

We load 100 rows, there are no stats, dynamic sampling kicks in, bingo the optimizer expects 100 rows.

Then for > 11.2.0.4 ( in this case 19.6), with the addition of SCOPE column in the script for 19c, we see that we now have table and column statistics after the load despite no explicit stats gathering call. Which, given the feature we’re discussing, should be completely obvious and expected.

I’ve used a temporary table here deliberately purely to facilitate a comment at the end. Clearly this could be a normal heap table – but the SCOPE in the output is specific to the new feature of temporary table private statistics.

Plan hash value: 3617692013
----------------------------------------------------------------------------------
| Id | Operation                   | Name | Rows | Bytes | Cost (%CPU)|     Time |
----------------------------------------------------------------------------------
|  0 | SELECT STATEMENT            |      |  100 | 11300 |      2  (0)| 00:00:01 |
|  1 | TABLE ACCESS STORAGE FULL   | T1   |  100 | 11300 |      2  (0)| 00:00:01 |
----------------------------------------------------------------------------------

Note
-----
  - Global temporary table session private statistics used


  NUM_ROWS SCOPE  
---------- -------
           SHARED 
       100 SESSION

COLUMN_NAME            NUM_NULLS NUM_DISTINCT SCOPE  
--------------------- ---------- ------------ -------
OBJECT_NAME                    0            7 SESSION
SUBOBJECT_NAME                 7           93 SESSION
OBJECT_ID                      0          100 SESSION
DATA_OBJECT_ID                 3           97 SESSION
OBJECT_TYPE                    0            3 SESSION
CREATED                        0           95 SESSION
LAST_DDL_TIME                  0           97 SESSION
TIMESTAMP                      0           96 SESSION
STATUS                         0            1 SESSION
TEMPORARY                      0            1 SESSION
GENERATED                      0            2 SESSION
SECONDARY                      0            1 SESSION
NAMESPACE                      0            1 SESSION
EDITION_NAME                 100            0 SESSION
SHARING                        0            1 SESSION
EDITIONABLE                  100            0 SESSION
ORACLE_MAINTAINED              0            1 SESSION
APPLICATION                    0            1 SESSION
DEFAULT_COLLATION             94            1 SESSION
DUPLICATED                     0            1 SESSION
SHARDED                        0            1 SESSION
CREATED_APPID                100            0 SESSION
CREATED_VSNID                100            0 SESSION
MODIFIED_APPID               100            0 SESSION
MODIFIED_VSNID               100            0 SESSION

Again, we’ve loaded 100 rows, as part of the direct path load, we have some base & column statstics, the optimizer expects 100 rows. No dynamic sampling necessary

But what if our data is loaded in multiple steps, might this new online statistics gathering cause us a bit of a problem?

It only gathers the stats when the segment is empty.

I’m not going to repeat the output above for the table & column statistics, just the execution plan detail.

drop table t1;
create global temporary table t1
on commit preserve rows
as
select * from user_objects where rownum <= 100;
insert /*+ append */ into t1
select * from user_objects
commit;

insert /*+ append */ into t1
select * from user_objects
commit;

explain plan for
select * from t1;

Which in 11.2.0.4 gives:

Plan hash value: 3617692013
---------------------------------------------------------------------------------------
| Id | Operation                      | Name |   Rows | Bytes | Cost (%CPU)|    Time  |
---------------------------------------------------------------------------------------
|  0 | SELECT STATEMENT               |      |  32376 | 6007K |    93   (0)| 00:00:01 |
|  1 | TABLE ACCESS STORAGE FULL      | T1   |  32376 | 6007K |    93   (0)| 00:00:01 |
---------------------------------------------------------------------------------------

Note
-----
  - dynamic sampling used for this statement (level=2)

select count(*) from t1;

  COUNT(*)
----------
     34392

And in 19.6

Plan hash value: 3617692013
----------------------------------------------------------------------------------
| Id | Operation                   | Name | Rows | Bytes | Cost (%CPU)|     Time |
----------------------------------------------------------------------------------
|  0 | SELECT STATEMENT            |      |  100 | 11300 |      2  (0)| 00:00:01 |
|  1 | TABLE ACCESS STORAGE FULL   | T1   |  100 | 11300 |      2  (0)| 00:00:01 |
----------------------------------------------------------------------------------

Note
-----
  - Global temporary table session private statistics used

select count(*) from t1;

  COUNT(*)
----------
     59712*

*With an obvious difference in actual rows, because these are different environments on different versions.

The problem now is that our subsequent processing code which drives off a table populated with different volumes of data in multiple stages used to work fine in 11.2.0.4 but is now at risk of some serious consequences from having cardinality mis-estimates thanks to inaccurate statistics from our new feature which is behaving as it should.

In our real-world example, it was not always the case that there was a big skew between the first load and the subsequent loads and actually this consequence, obvious in hindsight, took a few weeks to reveal itself until that first load into an empty segment happened to be very small followed by some other loads which were much larger.

Furthermore, this also involved the private temporary table aspect and so when you’re looking at solutions, you might consider whether some explicit stats gathering at the end of the load is the solution – in which case should it be private stats or shared stats or whether it even matters when quite possibly the easiest solution is to just use dynamic sampling in the subsequent select/s.

I was reminded of this issue when writing this other article earlier on a more serious problem that online statistics gathering was causing:

COMPATIBLE Identifier Intrigue

An observation about a crucial difference whilst testing an upgrade with / without COMPATIBLE.

Upgrade from 11.2.0.4 to 19.6
Initial upgrade testing done with default COMPATIBLE of 19.0.0
Another enviroment was upgraded with COMPATIBLE set to 11.2.0.4.0, rationale being that it allowed for “easy” downgrade should we run into unresolvable issues.

For background reason, please see Mike Dietrich blog on COMPATIBLE: https://mikedietrichde.com/2019/04/17/when-and-how-should-you-change-compatible/
I am not criticising this article at all.
There is an example in the blog about identifier being such a feature impacted by COMPATIBLE.And there are some interesting points in the discussions about the impact of testing.

We had an issue with a view on top of a PIVOT query.
PIVOT is slightly unusual in that the resulting column names are dynamic.

This example is a bit ridiculous… however… Let’s say we had a pivot a bit like this:

select owner, created_year, "January can be a cold month _T"
  from (
         select owner
              , to_number(to_char(created,'YYYY')) created_year
              , to_char(created,'MON') created_month
              , object_type
           from dba_objects
           where owner in ('SYSTEM','SYS')
       )
pivot (
         max(object_type) as type, count(*) as cnt for created_month in
         ('JAN' as "January can be a cold month "
         ,'FEB' as "February can be a bit miser"
         ,'MAR' as "Mad as a Hare"
         ,'APR' as "Showers"
         ,'MAY' as "Can be magnificent"
         ,'JUN' as "Flamin'"
         ,'JUL' as "Peak Summer"
         ,'AUG' as "Often disappointing"
         ,'SEP' as "Always a bonus"
         ,'OCT' AS "Neither here nor there"
         ,'NOV' as "All the best babies born he"
         ,'DEC' as "Christmas? Already?")
       )
order
    by owner
     , created_year;
OWNER                          CREATED_YEAR January can be a co
------------------------------ ------------ -------------------
SYS                                    2014
SYS                                    2015
SYS                                    2016 DIRECTORY
SYS                                    2017
SYS                                    2018 TABLE SUBPARTITION
SYS                                    2019
SYS                                    2020
SYS                                    2021 TABLE PARTITION
SYSTEM                                 2014                    

9 rows selected.

You can see our final column selection (which might be a view definition in the real world ?!?!??!), is relying on the 11g implicit identifier truncation to 30 characters of “January can be a cold month _T”.
Unwise… in hindsight.

So we fix this and release it to our default 19.6 COMPATIBLE database.

select owner, created_year, "January can be a cold month _TYPE"
  from (
         select owner
              , to_number(to_char(created,'YYYY')) created_year
              , to_char(created,'MON') created_month
              , object_type
           from dba_objects
           where owner in ('SYSTEM','SYS')
       )
pivot (
         max(object_type) as type, count(*) as cnt for created_month in
         ('JAN' as "January can be a cold month "
         ,'FEB' as "February can be a bit miser"
         ,'MAR' as "Mad as a Hare"
         ,'APR' as "Showers"
         ,'MAY' as "Can be magnificent"
         ,'JUN' as "Flamin'"
         ,'JUL' as "Peak Summer"
         ,'AUG' as "Often disappointing"
         ,'SEP' as "Always a bonus"
         ,'OCT' AS "Neither here nor there"
         ,'NOV' as "All the best babies born he"
         ,'DEC' as "Christmas? Already?")
       )
order
    by owner
     , created_year;
	 OWNER      CREATED_YEAR January can be a cold m
---------- ------------ -----------------------
SYS                2015
SYS                2016 DIRECTORY
SYS                2017
SYS                2018
SYS                2019
SYS                2020
SYS                2021 VIEW
SYSTEM             2015
SYSTEM             2021 VIEW                   

9 rows selected.

And then we release it to the other compatible = 11.2.0.4 19c database. Well, I’m sure that there aren’t going to be any surprises that it doesn’t bloody work:

select owner, created_year, "January can be a cold month _TYPE"
  from (
         select owner
              , to_number(to_char(created,'YYYY')) created_year
              , to_char(created,'MON') created_month
              , object_type
           from dba_objects
           where owner in ('SYSTEM','SYS')
       )
pivot (
         max(object_type) as type, count(*) as cnt for created_month in
         ('JAN' as "January can be a cold month "
         ,'FEB' as "February can be a bit miser"
         ,'MAR' as "Mad as a Hare"
         ,'APR' as "Showers"
         ,'MAY' as "Can be magnificent"
         ,'JUN' as "Flamin'"
         ,'JUL' as "Peak Summer"
         ,'AUG' as "Often disappointing"
         ,'SEP' as "Always a bonus"
         ,'OCT' AS "Neither here nor there"
         ,'NOV' as "All the best babies born he"
         ,'DEC' as "Christmas? Already?")
       )
order
    by owner
     , created_year;
ORA-00972: identifier is too long
00972. 00000 -  "identifier is too long"
*Cause:    An identifier with more than 30 characters was specified.
*Action:   Specify at most 30 characters.
Error at Line: 128 Column: 29

So what?
We just use the old one right?
No – it doesn’t bloody work either:

select owner, created_year, "January can be a cold month _T"
  from (
         select owner
              , to_number(to_char(created,'YYYY')) created_year
              , to_char(created,'MON') created_month
              , object_type
           from dba_objects
           where owner in ('SYSTEM','SYS')
       )
pivot (
         max(object_type) as type, count(*) as cnt for created_month in
         ('JAN' as "January can be a cold month "
         ,'FEB' as "February can be a bit miser"
         ,'MAR' as "Mad as a Hare"
         ,'APR' as "Showers"
         ,'MAY' as "Can be magnificent"
         ,'JUN' as "Flamin'"
         ,'JUL' as "Peak Summer"
         ,'AUG' as "Often disappointing"
         ,'SEP' as "Always a bonus"
         ,'OCT' AS "Neither here nor there"
         ,'NOV' as "All the best babies born he"
         ,'DEC' as "Christmas? Already?")
       )
order
    by owner
     , created_year;
ORA-00904: "January can be a cold month _T": invalid identifier
00904. 00000 -  "%s: invalid identifier"
*Cause:
*Action:
Error at Line: 100 Column: 29

Fair enough… What should it be then Mr Compatible?
Give us a clue:

select *
  from (
         select owner
              , to_number(to_char(created,'YYYY')) created_year
              , to_char(created,'MON') created_month
              , object_type
           from dba_objects
           where owner in ('SYSTEM','SYS')
       )
pivot (
         max(object_type) as type, count(*) as cnt for created_month in
         ('JAN' as "January can be a cold month "
         ,'FEB' as "February can be a bit miser"
         ,'MAR' as "Mad as a Hare"
         ,'APR' as "Showers"
         ,'MAY' as "Can be magnificent"
         ,'JUN' as "Flamin'"
         ,'JUL' as "Peak Summer"
         ,'AUG' as "Often disappointing"
         ,'SEP' as "Always a bonus"
         ,'OCT' AS "Neither here nor there"
         ,'NOV' as "All the best babies born he"
         ,'DEC' as "Christmas? Already?")
       )
order
    by owner
     , created_year;
OWNER      CREATED_YEAR January can be a cold m
---------- ------------ -----------------------
SYS                2015
SYS                2016 DIRECTORY
SYS                2017
SYS                2018
SYS                2019
SYS                2020 TABLE PARTITION
SYS                2021 VIEW
SYSTEM             2015
SYSTEM             2021 VIEW

Ok. Give me a bit more of a clue please:

create table dom1 as
select *
  from (
         select owner
              , to_number(to_char(created,'YYYY')) created_year
              , to_char(created,'MON') created_month
              , object_type
           from all_objects
           where owner in ('SYSTEM','SYS')
       )
pivot (
         max(object_type) as type for created_month in
         ('JAN' as "January can be a cold month ")
       )
order
    by owner
     , created_year;

Table DOM1 created.
select * from dom1;
OWNER      CREATED_YEAR January can be a cold m
---------- ------------ -----------------------
SYS                2015
SYS                2016
SYS                2017
SYS                2018
SYS                2019
SYS                2021 VIEW
SYSTEM             2015
SYSTEM             2021 VIEW

You’re playing hard to get…

select listagg('"'||column_name||'"',',') within group(order by column_id) from user_tab_columns where table_name = 'DOM1';
LISTAGG('"'||COLUMN_NAME||'"',',')WITHINGROUP(ORDERBYCOLUMN_ID)
-----------------------------------------------------------------
"OWNER","CREATED_YEAR","January can be a cold month _TYPE"
select "OWNER","CREATED_YEAR","January can be a cold month _TYPE" from dom1;
ORA-00972: identifier is too long
00972. 00000 -  "identifier is too long"
*Cause:    An identifier with more than 30 characters was specified.
*Action:   Specify at most 30 characters.
Error at Line: 225 Column: 36&lt;/code&gt;&lt;/pre&gt;
select "OWNER","CREATED_YEAR","January can be a cold month _TYPE"
from (select *
  from (
         select owner
              , to_number(to_char(created,'YYYY')) created_year
              , to_char(created,'MON') created_month
              , object_type
           from all_objects
           where owner in ('SYSTEM','SYS')
       )
pivot (
         max(object_type) as type for created_month in
         ('JAN' as "January can be a cold month ")
       )
order
    by owner;
ORA-00972: identifier is too long
00972. 00000 -  "identifier is too long"
*Cause:    An identifier with more than 30 characters was specified.
*Action:   Specify at most 30 characters.
Error at Line: 227 Column: 31

OK… enough already… I’m not playing these games 🙂

The obvious solution is not to go anywhere near the limit in the first place. This was just a bit of messing around.

Exchange Partition Validation

Testing an upgrade from 11.2.0.4 to 19.6, we observed a very significant degradation in partition exchange performance.

Is it a case of expected behaviour or not?

The documentation is quite clear in both 11.2 and 19c:

https://docs.oracle.com/cd/E11882_01/server.112/e25523/part_admin002.htm#i1107555

https://docs.oracle.com/en/database/oracle/oracle-database/19/vldbg/maintenance-partition-tables-indexes.html#GUID-E08650B4-06B1-43F9-91B0-FBF685A3B848

When you specify WITHOUT VALIDATION for the exchange partition operation, this is normally a fast operation because it involves only data dictionary updates. However, if the table or partitioned table involved in the exchange operation has a primary key or unique constraint enabled, then the exchange operation is performed as if WITH VALIDATION were specified to maintain the integrity of the constraints.

Personally, in a data warehouse with exchange partition I would tend to have defined such a constraint as ENABLE NOVALIDATE if it was even required.

The CONSTRAINT is a PK constraint backed up a local index, partition keys as leading columns.

The trace file points to a clear culprit:

 select /*+ first_rows(1) ordered */ 1 
 from "X"."FB_P_161261_SP_9" A? ,"X"."FACILITY_BALANCE" B 
 where "A"."SNAPSHOT_ID" = "B"."SNAPSHOT_ID" and "A"."SNAPSHOT_VERSION" = "B"."SNAPSHOT_VERSION" and "A"."FACILITY_BALANCE_ID" = "B"."FACILITY_BALANCE_ID" and "A"."VERSION" = "B"."VERSION" 
 and ( tbl$or$idx$part$num("X"."FACILITY_BALANCE",0,0,0 ,B? .rowid )  <  62358 or  tbl$or$idx$part$num("X"."FACILITY_BALANCE",0,0,0 ,B? .rowid )  >  62358 ) 
 and tbl$or$idx$part$num("X"."FACILITY_BALANCE",0,0,0 ,A? ."SNAPSHOT_ID" ,A? ."SNAPSHOT_VERSION" )  <>  62358 and rownum < 2


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      8.40       8.46          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1   4229.27    5278.73   27688674   27783294          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3   4237.67    5287.20   27688674   27783294          0           0 

We know from Jonathan Lewis’s work on http://www.nocoug.org/download/2008-11/partitioning_NOCOUG.pdf that this is expected internal SQL from a ENABLE VALIDATE constraint in an EXCHANGE WITHOUT VALIDATION scenario

So why the big change in performance?

Probably this is an indication of just a simple execution plan issue. I would need to trace the same in 11g to confirm which is easier said than done under the circumstances.

This is the info from the 19c tkprof at least:

Rows (1st) Rows (avg) Rows (max) Row Source Operation

---------- ---------- ---------- ---------------------------------------------------
         0          0          0 COUNT STOPKEY (cr=27783294 pr=27688674 pw=0 time=287636041 us starts=1)
         0          0          0  NESTED LOOPS (cr=27783294 pr=27688674 pw=0 time=287636035 us starts=1 cost=4 size=1061 card=1)
 238651024  238651024  238651024   VIEW VW_JF_SET$91EDBF25 (cr=27783288 pr=27688673 pw=0 time=3245932610 us starts=1 cost=4 size=62 card=2)
 238651024  238651024  238651024    UNION-ALL (cr=27783288 pr=27688673 pw=0 time=2708356160 us starts=1)
  11351302   11351302   11351302     PARTITION COMBINED ITERATOR PARTITION: KEY KEY (cr=69570 pr=69469 pw=0 time=5491712 us starts=1 cost=2 size=43 card=1)
  11351302   11351302   11351302      INDEX STORAGE FAST FULL SCAN FIRST ROWS PK_FACILITY_BALANCE PARTITION: KEY KEY (cr=69570 pr=69469 pw=0 time=4380693 us starts=20 cost=2 size=43 card=1)(object id 42709299)
 227299722  227299722  227299722     PARTITION COMBINED ITERATOR PARTITION: KEY KEY (cr=27713718 pr=27619204 pw=0 time=2376271490 us starts=1 cost=2 size=43 card=1)
 227299722  227299722  227299722      INDEX STORAGE FAST FULL SCAN FIRST ROWS PK_FACILITY_BALANCE PARTITION: KEY KEY (cr=27713718 pr=27619204 pw=0 time=1916674628 us starts=62357 cost=2 size=43 card=1)(object id 42709299)
         0          0          0   INDEX UNIQUE SCAN FB_P_161261_SP_9$C3 (cr=6 pr=1 pw=0 time=1734545604 us starts=238651024 cost=0 size=1030 card=1)(object id 72993779)  
		

What is clear is that if the constraint definition is changed to ENABLE NOVALIDATE then the exchange partition takes about 1 minute. Which still feels a bit slow but a heck of a lot better than 90 minutes.

If you see Mohamed Houri’s comment below, this experience is not isolated and in his case, they went for EXCHANGE PARTITION (WITH VALIDATION). After the Christmas break, I will re-evaluate the choice I made.

Parallel Window Consolidator Calls The Stops

Sharing observations of performance issue arising out of testing 19.6 upgrade from 11.2.0.4 (bug possibly from 12+ looking at the fixes which work).

Sharing this one in particular as it doesn’t seem that common from anecdotal evidence (forums, blogs, support), it doesn’t appear fixed yet, progress with support has been disappointing, however circumstances don’t seem particularly niche.

We’ve had a few issues with a number of parallel queries just “hanging” forever.

Issue seems to be related to WINDOW CONSOLIDATOR and the parallel distribution method.

Haven’t been able to find a good matching bug via Oracle Support (nor happy with the progress of SR with them) but found a good match on a Lothar Flatz blog post which led me to the PQ_DISTRIBUTE_WINDOW as cause.

SQL contains parallel + join to view, view contains analytic
SQL Executes in under a second “normally”.

Without a fix, the SQL will just hang for a long time. The longest I’ve left it is 3 days but given the wait states of the sessions involved, there’s no reason to think it would stop of its own accord.

Jumping ahead to the workarounds which work, any of the following:

  • Turn off fix_control 13345888 via alter session or opt_param
  • Turn off “_adaptive_window_consolidator_enabled” via alter session/system or opt_param
  • Hint a PQ distribution method other than 2. 3 doesn’t work here so 1 is the other option – PQ_DISTRIBUTE_WINDOW(@query_block 1)

Here we see some evidence from just now, running for nearly 30 minutes:

select s.inst_id i,s.sid,s.serial#,s.module
 ,      s.blocking_session blks,s.blocking_instance bi,s.final_blocking_session f_blk_s, s.final_blocking_instance fbi
 ,      CASE WHEN state != 'WAITING' THEN 'WORKING' ELSE 'WAITING' END AS state
 ,      CASE WHEN state != 'WAITING' THEN 'On CPU / runqueue' ELSE event END AS sw_event, s.seconds_in_wait wait
 ,      s.sql_id,s.sql_exec_id,to_char(s.sql_exec_start,'DD-MON-YYYY HH24:MI:SS') exec_start
 from   gv$session    s
 where  sql_id = '5xyrp7v4djagv';

         I        SID    SERIAL# MODULE                     BLKS         BI    F_BLK_S        FBI STATE   SW_EVENT                        WAIT SQL_ID        SQL_EXEC_ID EXEC_START                   
---------- ---------- ---------- -------------------- ---------- ---------- ---------- ---------- ------- ------------------------- ---------- ------------- ----------- -----------------------------
         2       2805      15947 SQL Developer                                                    WAITING PX Deq: Execution Msg           1492 5xyrp7v4djagv    33554434 26-OCT-2020 12:18:59         
         2       3095       3608 SQL Developer                                                    WAITING PX Deq: Execution Msg           1492 5xyrp7v4djagv    33554434 26-OCT-2020 12:18:59         
         2       3367      28066 SQL Developer                                                    WAITING PX Deq: Execution Msg           1492 5xyrp7v4djagv    33554434 26-OCT-2020 12:18:59         
         2       5610       8452 SQL Developer                                                    WAITING PX Deq: Table Q Normal          1492 5xyrp7v4djagv    33554434 26-OCT-2020 12:18:59         
         2       5885      54481 SQL Developer              9672          2       9672          2 WAITING PX Deq: Execute Reply           1492 5xyrp7v4djagv    33554434 26-OCT-2020 12:18:59         
         2       8828      57832 SQL Developer                                                    WAITING PX Deq: Execution Msg           1492 5xyrp7v4djagv    33554434 26-OCT-2020 12:18:59         
         2       9111      37143 SQL Developer                                                    WAITING PX Deq: Execution Msg           1492 5xyrp7v4djagv    33554434 26-OCT-2020 12:18:59         
         2       9383      50792 SQL Developer                                                    WAITING PX Deq: Execution Msg           1492 5xyrp7v4djagv    33554434 26-OCT-2020 12:18:59         
         2       9672      29993 SQL Developer                                                    WAITING PX Deq: Execution Msg           1492 5xyrp7v4djagv    33554434 26-OCT-2020 12:18:59         

Real-time SQL Monitoring report looks per below (note Duration compared to any other progress/metrics)… note that in later versions of Oracle, RTSM has a habit of timing out and reporting DONE(ERROR) even though the SQL is still going:



 Global Information
 ------------------------------
 Status              :  EXECUTING                  
 Instance ID         :  2                          
 SQL ID              :  5xyrp7v4djagv              
 SQL Execution ID    :  33554434                   
 Execution Started   :  10/26/2020 12:18:59        
 First Refresh Time  :  10/26/2020 12:18:59        
 Last Refresh Time   :  10/26/2020 12:18:59        
 Duration            :  1592s                      
 Module/Action       :  SQL Developer/-            
 Service             :  LNTDH8U.UK.DB.COM          
 Program             :  SQL Developer              


Global Stats
=========================================
| Elapsed |   Cpu   |  Other   | Buffer |
| Time(s) | Time(s) | Waits(s) |  Gets  |
=========================================
|    0.00 |    0.00 |     0.00 |      3 |
=========================================

Parallel Execution Details (DOP=4 , Servers Allocated=8)
==========================================================================================
|      Name      | Type  | Server# | Elapsed |   Cpu   |  Other   | Buffer | Wait Events |
|                |       |         | Time(s) | Time(s) | Waits(s) |  Gets  | (sample #)  |
==========================================================================================
| PX Coordinator | QC    |         |    0.00 |    0.00 |     0.00 |      3 |             |
| p000           | Set 1 |       1 |         |         |          |        |             |
| p001           | Set 1 |       2 |         |         |          |        |             |
| p002           | Set 1 |       3 |         |         |          |        |             |
| p003           | Set 1 |       4 |         |         |          |        |             |
| p004           | Set 2 |       1 |         |         |          |        |             |
| p005           | Set 2 |       2 |         |         |          |        |             |
| p006           | Set 2 |       3 |         |         |          |        |             |
| p007           | Set 2 |       4 |         |         |          |        |             |
==========================================================================================

SQL Plan Monitoring Details (Plan Hash Value=3844894891)
===============================================================================================================================================================================================
| Id   |                           Operation                           |              Name              |  Rows   | Cost |   Time    | Start  | Execs |   Rows   | Activity | Activity Detail |
|      |                                                               |                                | (Estim) |      | Active(s) | Active |       | (Actual) |   (%)    |   (# samples)   |
===============================================================================================================================================================================================
|    0 | SELECT STATEMENT                                              |                                |         |      |           |        |     1 |          |          |                 |
| -> 1 |   PX COORDINATOR                                              |                                |         |      |         1 |     +0 |     1 |        0 |   100.00 | Cpu (1)         |
|    2 |    PX SEND QC (RANDOM)                                        | :TQ20006                       |      2M |  445 |           |        |       |          |          |                 |
|    3 |     HASH JOIN                                                 |                                |      2M |  445 |           |        |       |          |          |                 |
|    4 |      PART JOIN FILTER CREATE                                  | :BF0000                        |     232 |  441 |           |        |       |          |          |                 |
|    5 |       PX RECEIVE                                              |                                |     232 |  441 |           |        |       |          |          |                 |
|    6 |        PX SEND BROADCAST                                      | :TQ20005                       |     232 |  441 |           |        |       |          |          |                 |
|    7 |         VIEW                                                  |                                |     232 |  441 |           |        |       |          |          |                 |
|    8 |          WINDOW CONSOLIDATOR BUFFER                           |                                |     232 |  441 |           |        |       |          |          |                 |
|    9 |           PX RECEIVE                                          |                                |     232 |  441 |           |        |       |          |          |                 |
|   10 |            PX SEND HASH                                       | :TQ20004                       |     232 |  441 |           |        |       |          |          |                 |
|   11 |             WINDOW BUFFER                                     |                                |     232 |  441 |           |        |       |          |          |                 |
|   12 |              HASH JOIN                                        |                                |     232 |  441 |           |        |       |          |          |                 |
|   13 |               NESTED LOOPS                                    |                                |     505 |    4 |           |        |       |          |          |                 |
|   14 |                TABLE ACCESS BY GLOBAL INDEX ROWID             | D_B                            |       1 |    3 |           |        |       |          |          |                 |
|   15 |                 PX RECEIVE                                    |                                |       1 |    2 |           |        |       |          |          |                 |
|   16 |                  PX SEND HASH (BLOCK ADDRESS)                 | :TQ20002                       |       1 |    2 |           |        |       |          |          |                 |
|   17 |                   PX SELECTOR                                 |                                |         |      |           |        |       |          |          |                 |
|   18 |                    INDEX UNIQUE SCAN                          | D_B_PK                         |       1 |    2 |           |        |       |          |          |                 |
|   19 |                INDEX FULL SCAN                                | D_R_UK01                       |     505 |    1 |           |        |       |          |          |                 |
|   20 |               PX RECEIVE                                      |                                |     108 |  437 |           |        |       |          |          |                 |
|   21 |                PX SEND BROADCAST                              | :TQ20003                       |     108 |  437 |           |        |       |          |          |                 |
|   22 |                 VIEW                                          | V_V2                           |     108 |  437 |           |        |       |          |          |                 |
|   23 |                  WINDOW CONSOLIDATOR BUFFER                   |                                |     108 |  437 |           |        |       |          |          |                 |
|   24 |                   PX RECEIVE                                  |                                |     108 |  437 |           |        |       |          |          |                 |
|   25 |                    PX SEND HASH                               | :TQ20001                       |     108 |  437 |           |        |       |          |          |                 |
|   26 |                     WINDOW SORT                               |                                |     108 |  437 |           |        |       |          |          |                 |
|   27 |                      NESTED LOOPS                             |                                |     108 |  436 |           |        |       |          |          |                 |
|   28 |                       NESTED LOOPS                            |                                |     108 |    4 |           |        |       |          |          |                 |
|   29 |                        TABLE ACCESS BY GLOBAL INDEX ROWID     | D_B                            |       1 |    3 |           |        |       |          |          |                 |
|   30 |                         PX RECEIVE                            |                                |       1 |    2 |           |        |       |          |          |                 |
|   31 |                          PX SEND HASH (BLOCK ADDRESS)         | :TQ20000                       |       1 |    2 |           |        |       |          |          |                 |
|   32 |                           PX SELECTOR                         |                                |         |      |           |        |       |          |          |                 |
|   33 |                            INDEX UNIQUE SCAN                  | D_B_PK                         |       1 |    2 |           |        |       |          |          |                 |
|   34 |                        INDEX RANGE SCAN                       | D_BS_UK01                      |     108 |    1 |           |        |       |          |          |                 |
|   35 |                       PX COORDINATOR                          |                                |         |      |           |        |       |          |          |                 |
|   36 |                        PX SEND QC (RANDOM)                    | :TQ10002                       |       1 |    4 |           |        |       |          |          |                 |
|   37 |                         BUFFER SORT                           |                                |      2M |      |           |        |       |          |          |                 |
|   38 |                          VIEW                                 | V_V1                           |       1 |    4 |           |        |       |          |          |                 |
|   39 |                           UNION ALL PUSHED PREDICATE          |                                |         |      |           |        |       |          |          |                 |
|   40 |                            TABLE ACCESS BY GLOBAL INDEX ROWID | D_S                            |       1 |    2 |           |        |       |          |          |                 |
|   41 |                             BUFFER SORT                       |                                |         |      |           |        |       |          |          |                 |
|   42 |                              PX RECEIVE                       |                                |       1 |    1 |           |        |       |          |          |                 |
|   43 |                               PX SEND HASH (BLOCK ADDRESS)    | :TQ10000                       |       1 |    1 |           |        |       |          |          |                 |
|   44 |                                PX SELECTOR                    |                                |         |      |           |        |       |          |          |                 |
|   45 |                                 INDEX UNIQUE SCAN             | D_S_PK                         |       1 |    1 |           |        |       |          |          |                 |
|   46 |                            TABLE ACCESS BY INDEX ROWID        | D_S                            |       1 |    2 |           |        |       |          |          |                 |
|   47 |                             BUFFER SORT                       |                                |         |      |           |        |       |          |          |                 |
|   48 |                              PX RECEIVE                       |                                |       1 |    1 |           |        |       |          |          |                 |
|   49 |                               PX SEND HASH (BLOCK ADDRESS)    | :TQ10001                       |       1 |    1 |           |        |       |          |          |                 |
|   50 |                                PX SELECTOR                    |                                |         |      |           |        |       |          |          |                 |
|   51 |                                 INDEX UNIQUE SCAN             | D_S                            |       1 |    1 |           |        |       |          |          |                 |
|   52 |      PX BLOCK ITERATOR ADAPTIVE                               |                                |    8255 |    3 |           |        |       |          |          |                 |
|   53 |       TABLE ACCESS STORAGE FULL                               | F_FACT                         |    8255 |    3 |           |        |       |          |          |                 |
===============================================================================================================================================================================================

ASH says it’s not doing anything (as we’d expect it to, being consistent with RTSM report above).


select count(*), min(sample_time), max(sample_time), sysdate from gv$active_session_history where sql_id = '5xyrp7v4djagv';

  COUNT(*) MIN(SAMPLE_TIME)             MAX(SAMPLE_TIME)             SYSDATE             
---------- ---------------------------- ---------------------------- --------------------
         1 26-OCT-20 12.18.59.828000000 26-OCT-20 12.18.59.828000000 26-OCT-2020 12:50:29

Miscellaneous Slave Info


select
decode(px.qcinst_id,NULL,'QC',
' - '||lower(substr(pp.SERVER_NAME,
length(pp.SERVER_NAME)-4,4) ) )"Username",
decode(px.qcinst_id,NULL, 'QC', '(Slave)') "QC/Slave" ,
to_char( px.server_set) "SlaveSet",
to_char(s.sid) "SID",
to_char(px.inst_id) "Slave INST",
decode(px.qcinst_id, NULL ,to_char(s.sid) ,px.qcsid) "QC SID",
to_char(px.qcinst_id) "QC INST",
px.req_degree "Req. DOP",
px.degree "Actual DOP"
from gv$px_session px,
gv$session s ,
gv$px_process pp
where px.sid=s.sid (+)
and px.serial#=s.serial#(+)
and px.inst_id = s.inst_id(+)
and px.sid = pp.sid (+)
and px.serial#=pp.serial#(+)
and s.sql_id = '5xyrp7v4djagv'
order by 6 , 1 desc
/

Usernam QC/Slav SlaveSet   SID       Slave INST QC SID     QC INST      Req. DOP  Actual DOP
------- ------- ---------- --------- ---------- ---------- -------- ------------- -----------
QC      QC                 5885       2          5885         
 - p007 (Slave) 2          9672       2          5885       2                   4          4
 - p006 (Slave) 2          3367       2          5885       2                   4          4
 - p005 (Slave) 2          9395       2          5885       2                   4          4
 - p004 (Slave) 2          3095       2          5885       2                   4          4
 - p003 (Slave) 1          9111       2          5885       2                   4          4
 - p002 (Slave) 1          2805       2          5885       2                   4          4
 - p001 (Slave) 1          8828       2          5885       2                   4          4
 - p000 (Slave) 1          5610       2          5885       2                   4          4

Detail! And don’t forget the notes…

…and how sparse tables can mess up your dynamic sampling.

A little lesson to self about paying attention to the detail, the obvious frickin’ detail. Getting older and slower.

We had one of those problems where a multitude of things were slow and yet there were no significant system-level problems (e.g. no general slow IO, no setting of the fast=false parameter, etc)

In such situations, if you check the high level system level metrics – AWR etc – and nothing is obvious then it makes sense to narrow the scope & drill into a specific problem, and distill that problem/statement as small as you can. If you can find the issue there then you might hope to find that that is the same as the wider problem and if not well you can just take that approach to every individual area,

I had a problem across a number of reporting modules, I picked on one module and from there I picked on the statement which was currently running and which was running for much longer than expected, I picked out one of the obvious problem joins within the problem statement and started looking at a simple two table join where the cardinality estimates were going wrong.

Most of the specific details of this plan and SQL can be ignored. It’s not important.

What is important is the cardinality difference.

And in fact, in this particular cut down example, the cardinality difference does not have the plan impact it does in the original setting.

 
set pages 999
explain plan for
SELECT /*+ parallel(4)*/
	   count(*)
FROM   psbal
LEFT OUTER JOIN
       prdct
ON    (prdct.d_product_id                        = psbal.d_product_id
AND    prdct.create_ts                           TO_TIMESTAMP('14.10.2020 08:16:34.822981', 'DD.MM.YYYY HH24:MI:SS.FF6'));

select * from table(dbms_xplan.display);

Plan hash value: 3885851338
--------------------------------------------------------------------------------------------------------------------------------------------------
|  Id | Operation                             | Name          | Rows | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |  TQ   |IN-OUT| PQ Distrib |
--------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                      |               |    1 |    72 |   3430K (3)| 01:54:22 |       |       |       |      |            |
|   1 |  SORT AGGREGATE                       |               |    1 |    72 |            |          |       |       |       |      |            |
|   2 |   PX COORDINATOR                      |               |      |       |            |          |       |       |       |      |            |
|   3 |    PX SEND QC (RANDOM)                | :TQ10003      |    1 |    72 |            |          |       |       | Q1,03 | P->S |  QC (RAND) |
|   4 |     SORT AGGREGATE                    |               |    1 |    72 |            |          |       |       | Q1,03 | PCWP |            |
|*  5 |      HASH JOIN                        |               | 7466M|   500G|   3430K (3)| 01:54:22 |       |       | Q1,03 | PCWP |            |
|   6 |       PART JOIN FILTER CREATE         | :BF0000       |  286K|  1680K|     56  (0)| 00:00:01 |       |       | Q1,03 | PCWP |            |
|   7 |        PX RECEIVE                     |               |  286K|  1680K|     56  (0)| 00:00:01 |       |       | Q1,03 | PCWP |            |
|   8 |         PX SEND BROADCAST             | :TQ10000      |  286K|  1680K|     56  (0)| 00:00:01 |       |       | Q1,00 | P->P |  BROADCAST |
|   9 |          PX BLOCK ITERATOR            |               |  286K|  1680K|     56  (0)| 00:00:01 |       |       | Q1,00 | PCWC |            |
|  10 |           INDEX STORAGE FAST FULL SCAN| S_PK          |  286K|  1680K|     56  (0)| 00:00:01 |       |       | Q1,00 | PCWP |            |
|* 11 |       HASH JOIN RIGHT OUTER           |               | 7466M|   458G|   3425K (3)| 01:54:12 |       |       | Q1,03 | PCWP |            |
|  12 |        PX RECEIVE                     |               |    1 |    30 |    306  (0)| 00:00:01 |       |       | Q1,03 | PCWP |            |
|  13 |         PX SEND BROADCAST             | :TQ10001      |    1 |    30 |    306  (0)| 00:00:01 |       |       | Q1,01 | P->P |  BROADCAST |
|  14 |          PX BLOCK ITERATOR            |               |    1 |    30 |    306  (0)| 00:00:01 |     1 |     3 | Q1,01 | PCWC |            |
|* 15 |           TABLE ACCESS STORAGE FULL   | PRODUCT       |    1 |    30 |    306  (0)| 00:00:01 |     1 |     3 | Q1,01 | PCWP |            |
|* 16 |        HASH JOIN                      |               | 7466M|   250G|   3420K (3)| 01:54:01 |       |       | Q1,03 | PCWP |            |
|  17 |         PX RECEIVE                    |               | 6903K|   118M|  16379  (1)| 00:00:33 |       |       | Q1,03 | PCWP |            |
|  18 |          PX SEND BROADCAST            | :TQ10002      | 6903K|   118M|  16379  (1)| 00:00:33 |       |       | Q1,02 | P->P |  BROADCAST |
|  19 |           PX BLOCK ITERATOR           |               | 6903K|   118M|  16379  (1)| 00:00:33 |     1 |     3 | Q1,02 | PCWC |            |
|* 20 |            TABLE ACCESS STORAGE FULL  | BOOK          | 6903K|   118M|  16379  (1)| 00:00:33 |     1 |     3 | Q1,02 | PCWP |            |
|  21 |         PX PARTITION LIST JOIN-FILTER |               | 8064M|   135G|   3398K (3)| 01:53:17 |:BF0000|:BF0000| Q1,03 | PCWC |            |
|  22 |          TABLE ACCESS STORAGE FULL    | BALANCE       | 8064M|   135G|   3398K (3)| 01:53:17 |:BF0000|:BF0000| Q1,03 | PCWP |            |
--------------------------------------------------------------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
  5 - access("FCT"."S_VID"="DNSP"."S_VID")
 11 - access("PRDCT"."PRODUCT_ID"(+)="FCT"."PRODUCT_ID")
 15 - storage(NVL("PRDCT"."MODIFY_TS"(+),TIMESTAMP' 9999-12-31 00:00:00')>TIMESTAMP' 2020-10-14 08:16:34.822981000' AND 
          "PRDCT"."CREATE_TS"(+)TIMESTAMP' 2020-10-14 08:16:34.822981000' AND 
         "PRDCT"."CREATE_TS"(+)<=TIMESTAMP' 2020-10-14 08:16:34.822981000')
 16 - access("BOOK_ID"="FCT"."BOOK_ID" AND "VERSION"="FCT"."BOOK_VERSION")
 20 - storage("COLUMN1" IS NULL OR "D_BOOK_VID"=(-2) OR "D_BOOK_VID"=(-1))
    filter("COLUMN1" IS NULL OR "D_BOOK_VID"=(-2) OR "D_BOOK_VID"=(-1))
 
Note
-----
  - dynamic sampling used for this statement (level=7)
  - Degree of Parallelism is 4 because of hint

and this:


set pages 999
explain plan for
select count(*)
FROM   prdct
WHERE  prdct.create_ts  <= TO_TIMESTAMP('14.10.2020 08:16:34.822981', 'DD.MM.YYYY HH24:MI:SS.FF6')
AND    NVL(prdct.modify_ts, DATE '9999-12-31')  > TO_TIMESTAMP('14.10.2020 08:16:34.822981', 'DD.MM.YYYY HH24:MI:SS.FF6');
   
select * from table(dbms_xplan.display);

Plan hash value: 2639949168
----------------------------------------------------------------------------------------------------
| Id | Operation                 | Name     | Rows | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
----------------------------------------------------------------------------------------------------
|  0 | SELECT STATEMENT          |          |    1 |    14 |   1103  (1)| 00:00:14 |       |       |
|  1 | SORT AGGREGATE            |          |    1 |    14 |            |          |       |       |
|  2 |  PARTITION LIST ALL       |          |  399 |  5586 |   1103  (1)| 00:00:14 |     1 |     3 |
|* 3 |  TABLE ACCESS STORAGE FULL| PRODUCT  |  399 |  5586 |   1103  (1)| 00:00:14 |     1 |     3 |
----------------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
  3 - storage(NVL("MODIFY_TS",TIMESTAMP' 9999-12-31 00:00:00')>TIMESTAMP' 2020-10-14 
       08:16:34.822981000' AND "CREATE_TS"<=TIMESTAMP' 2020-10-14 08:16:34.822981000')
    filter(NVL("MODIFY_TS",TIMESTAMP' 9999-12-31 00:00:00')>TIMESTAMP' 2020-10-14 
       08:16:34.822981000' AND "CREATE_TS"<=TIMESTAMP' 2020-10-14 08:16:34.822981000')

Once you see the problem, you can’t unsee it but for whatever reason, for ages, I was focusing on why there would be such a cardinality difference between A and B for what are basically the single table cardinality estimates for the same table without seeing the explanation right there in front of me.


Note
-----
  - dynamic sampling used for this statement (level=7)

I then got distracted and spent some time investigating why dynamic sampling was kicking in. Parallel query has different rules about when it can kick in. And I found reasons why it might.

But then I put that thought to one side.

Why is dynamic sampling saying this will return 1 row?

This is a small table and the estimate should be accurate and we like dynamic sampling so we want to show the feature to its full capability whenever and wherever it kicks in

Sure enough, as we might expect, if I hint dynamic sampling on the single table, estimate is one.


set pages 999
explain plan for
select /*+ dynamic_sampling(4) */ count(*)
FROM  prdct
WHERE prdct.create_ts                  <= TO_TIMESTAMP('14.10.2020 08:16:34.822981', 'DD.MM.YYYY HH24:MI:SS.FF6')
AND  NVL(prdct.modify_ts, DATE '9999-12-31')      > TO_TIMESTAMP('14.10.2020 08:16:34.822981', 'DD.MM.YYYY HH24:MI:SS.FF6');
   
select * from table(dbms_xplan.display);

----------------------------------------------------------------------------------------------------
| Id | Operation                 | Name     | Rows | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
----------------------------------------------------------------------------------------------------
|  0 | SELECT STATEMENT          |          |    1 |    14 |   1103  (1)| 00:00:14 |       |       |
|  1 | SORT AGGREGATE            |          |    1 |    14 |            |          |       |       |
|  2 |  PARTITION LIST ALL       |          |    1 |    14 |   1103  (1)| 00:00:14 |     1 |     3 |
|* 3 |  TABLE ACCESS STORAGE FULL| PRODUCT  |    1 |    14 |   1103  (1)| 00:00:14 |     1 |     3 |
----------------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
  3 - storage(NVL("MODIFY_TS",TIMESTAMP' 9999-12-31 00:00:00')>TIMESTAMP' 2020-10-14 
       08:16:34.822981000' AND "CREATE_TS"<=TIMESTAMP' 2020-10-14 08:16:34.822981000')
    filter(NVL("MODIFY_TS",TIMESTAMP' 9999-12-31 00:00:00')>TIMESTAMP' 2020-10-14 
       08:16:34.822981000' AND "CREATE_TS"<=TIMESTAMP' 2020-10-14 08:16:34.822981000')
 
Note
-----
  - dynamic sampling used for this statement (level=4)

Without access to the sample statements, what suggestive evidence can we find?


select table_name, num_rows, blocks, avg_row_len
from  user_tables
where table_name = 'PRODUCT';

TABLE_NAME                       NUM_ROWS     BLOCKS AVG_ROW_LEN
------------------------------ ---------- ---------- -----------
PRODUCT                               462       4064         193

So that’s not a lot of rows in a lot more blocks than should be necessary.

At this point, we should go off and find out what the reasons might be.

For what it’s worth, for this application, my suspicions are historic direct path maintenance code coupled with table partitioning on status (LATEST/SUPERSEDED) and therefore row movement means an update is a delete + insert, coupled with periods of very low rate of change and small row sizes.

So we end up with old rows moving partition – using a new block for the updated version and leaving behind an empty block where the version was before the update and then relatively few new version rows per run which are using new blocks, and so lots of empty blocks.

i.e. sparsely populated table.

And then dynamic sampling kicks in and samples a bunch of blocks, and finds few actual rows from those samples and comes up with a low estimate and then the whole problem starts. And these were shared tables across the reporting modules so it had a reasonable wide impact.

It would be nice to back this up with some trace files detailing any of the dynamic sampling numbers but I don’t have access by default and mocking this all up outside of work is always a worthwhile exercise but just takes up so much time.

Anyway… move some partitions, rebuild some indexes and 4000 blocks becomes just over 40.

Now our dynamic sampling is looking much better:


----------------------------------------------------------------------------------------------------
| Id | Operation                 | Name     | Rows | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
----------------------------------------------------------------------------------------------------
|  0 | SELECT STATEMENT          |          |   1 |     14 |   1103  (1)| 00:00:14 |       |       |
|  1 | SORT AGGREGATE            |          |   1 |     14 |            |          |       |       |
|  2 |  PARTITION LIST ALL       |          | 297 |     14 |   1103  (1)| 00:00:14 |     1 |     3 |
|* 3 |  TABLE ACCESS STORAGE FULL| PRODUCT  | 297 |     14 |   1103  (1)| 00:00:14 |     1 |     3 |
----------------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
  3 - storage(NVL("MODIFY_TS",TIMESTAMP' 9999-12-31 00:00:00')>TIMESTAMP' 2020-10-14 
       08:16:34.822981000' AND "CREATE_TS"<=TIMESTAMP' 2020-10-14 08:16:34.822981000')
    filter(NVL("MODIFY_TS",TIMESTAMP' 9999-12-31 00:00:00')>TIMESTAMP' 2020-10-14 
       08:16:34.822981000' AND "CREATE_TS"<=TIMESTAMP' 2020-10-14 08:16:34.822981000')
 
Note
-----
  - dynamic sampling used for this statement (level=4)

Exercise repeated for a whole bunch of tables in a similar situation and everything across the board is a lot healthier.

Materialize cardinality

Blowing the dust off the blog with a couple of trivial observations.

Firstly, this little one about one implication of materialize.

I’ve always been a fan of the simplicity of the materialize hint as a quick fix for certain plan stability/performance issues but it comes at a clear cost of actually materialising to temp that subquery and is often used when actually a combination of no_merge, no_unnest and/or no_push_pred might be better choice.

Having been recently working on a platform with a problematic systemic temp addiction, I rarely use it unless I know the cost of materialising that resultset once is cheaper than querying the data the requisite number of times via any alternative method particularly on Exadata where the overhead of querying the data twice might be less than you think (note to self: might be helpful to demo this in a future post).

Here is another implication of materialize on the cardinality of a set of data.

This simulates a real world problem observation where the view contained a materialize hint.

Starting with some data – one day for each of April, five versions per day, between 0 and 5 versions potentially approved each day:

drop table  ref_data_versions;

create table ref_data_versions
(business_date   DATE
,version         NUMBER
,status          VARCHAR2(10));


insert into ref_data_versions
select to_date(20200401,'YYYYMMDD') + days.rn-1
,      versions.rn
,      CASE when versions.rn = round(dbms_random.value(1,5)) then 'APPROVED' ELSE 'UNAPPROVED' END
from   dual
cross join
       (select rownum rn from xmltable('1 to 30')) days
cross join
       (select rownum rn from xmltable('1 to 5')) versions;
       
commit;

select count(*) from ref_data_versions;

The following query represents our view and happens to show the tangential observation that the optimizer does not recognize that the row_number analytic will filter any rows.

explain plan for 
with x as
(select /*+ */ *
 from   (select rdv.*
         ,      row_number() over (partition by business_date order by decode(status,'APPROVED',1,2), version DESC) rnk
         from   ref_data_versions rdv)
 where  rnk = 1)
select * 
from   x;
 
select * from table(dbms_xplan.display);
PLAN_TABLE_OUTPUT
Plan hash value: 2125428461
 
----------------------------------------------------------------------------------------------
| Id  | Operation                | Name              | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT         |                   |   150 |  6300 |     4  (25)| 00:00:01 |
|*  1 |  VIEW                    |                   |   150 |  6300 |     4  (25)| 00:00:01 |
|*  2 |   WINDOW SORT PUSHED RANK|                   |   150 |  4350 |     4  (25)| 00:00:01 |
|   3 |    TABLE ACCESS FULL     | REF_DATA_VERSIONS |   150 |  4350 |     3   (0)| 00:00:01 |
----------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   1 - filter("RNK"=1)
   2 - filter(ROW_NUMBER() OVER ( PARTITION BY "BUSINESS_DATE" ORDER BY 
              DECODE("STATUS",'APPROVED',1,2),INTERNAL_FUNCTION("VERSION") DESC )<=1)
 
Note
-----
   - dynamic statistics used: dynamic sampling (level=2)

If we add in a predicate on business date, we get:

explain plan for 
with x as
(select /*+ */ *
 from   (select rdv.*
         ,      row_number() over (partition by business_date order by decode(status,'APPROVED',1,2), version DESC) rnk
         from   ref_data_versions rdv)
 where  rnk = 1)
select * 
from   x
where  business_date = to_date(20200429,'YYYYMMDD');
 
select * from table(dbms_xplan.display);
Plan hash value: 2125428461
 
----------------------------------------------------------------------------------------------
| Id  | Operation                | Name              | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT         |                   |     5 |   210 |     4  (25)| 00:00:01 |
|*  1 |  VIEW                    |                   |     5 |   210 |     4  (25)| 00:00:01 |
|*  2 |   WINDOW SORT PUSHED RANK|                   |     5 |   145 |     4  (25)| 00:00:01 |
|*  3 |    TABLE ACCESS FULL     | REF_DATA_VERSIONS |     5 |   145 |     3   (0)| 00:00:01 |
----------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   1 - filter("RNK"=1)
   2 - filter(ROW_NUMBER() OVER ( PARTITION BY "BUSINESS_DATE" ORDER BY 
              DECODE("STATUS",'APPROVED',1,2),INTERNAL_FUNCTION("VERSION") DESC )<=1)
   3 - filter("RDV"."BUSINESS_DATE"=TO_DATE(' 2020-04-29 00:00:00', 'syyyy-mm-dd 
              hh24:mi:ss'))
 
Note
-----
   - dynamic statistics used: dynamic sampling (level=2)

Note that the query expects to get 5 rows rather than 1, but that’s consistent with what we saw before.

What happens if the subquery uses materialize:

explain plan for 
with x as
(select /*+ materialize */ *
 from   (select rdv.*
         ,      row_number() over (partition by business_date order by decode(status,'APPROVED',1,2), version DESC) rnk
         from   ref_data_versions rdv)
 where  rnk = 1)
select * 
from   x
where  business_date = to_date(20200429,'YYYYMMDD');
 
select * from table(dbms_xplan.display);
Plan hash value: 1377080515
 
------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                | Name                        | Rows  | Bytes | Cost (%CPU)| Time     |
------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                         |                             |   150 |  6300 |     6  (17)| 00:00:01 |
|   1 |  TEMP TABLE TRANSFORMATION               |                             |       |       |            |          |
|   2 |   LOAD AS SELECT (CURSOR DURATION MEMORY)| SYS_TEMP_0FD9D787C_3AB51228 |       |       |            |          |
|*  3 |    VIEW                                  |                             |   150 |  6300 |     4  (25)| 00:00:01 |
|*  4 |     WINDOW SORT PUSHED RANK              |                             |   150 |  4350 |     4  (25)| 00:00:01 |
|   5 |      TABLE ACCESS FULL                   | REF_DATA_VERSIONS           |   150 |  4350 |     3   (0)| 00:00:01 |
|*  6 |   VIEW                                   |                             |   150 |  6300 |     2   (0)| 00:00:01 |
|   7 |    TABLE ACCESS FULL                     | SYS_TEMP_0FD9D787C_3AB51228 |   150 |  6300 |     2   (0)| 00:00:01 |
------------------------------------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   3 - filter("RNK"=1)
   4 - filter(ROW_NUMBER() OVER ( PARTITION BY "BUSINESS_DATE" ORDER BY 
              DECODE("STATUS",'APPROVED',1,2),INTERNAL_FUNCTION("VERSION") DESC )<=1)
   6 - filter("BUSINESS_DATE"=TO_DATE(' 2020-04-29 00:00:00', 'syyyy-mm-dd hh24:mi:ss'))

The filter at step 6 is now no longer having any effect on the overall cardinality.

There are approaches using cardinality and opt_estimate which you might use to address some of the underlying issues.

However, just another example of why you should think twice about the liberal application of materialize hints (or any hints!).

The system with the problem was 11.2.0.4. Examples above are run on LiveSQL which is currently 19.

Outer Join with OR and Lateral View Decorrelation

Use of ANSI SQL is a personal thing.

Historically I have not been a fan apart from where it makes things easier/possible.

This reticence was mainly due to optimizer bugs and limitations in the earlier days.

Recently I have been using it much more because I find that the developers I interact with prefer it / understand it better.

You might/should be aware that Oracle will rewrite ANSI SQL to an Oracle syntax representation, this transformation being listed in the optimizer trace file.

You might/should also be aware that Oracle outer join syntax does not allow OR or IN:

drop table t1;
drop table t2;

create table t1
as
select floor((rownum+1)/2) col1
,      case when mod(rownum,2) = 0 then 1 else 2 end col2
,      10 col3
from   dual
connect by rownum <= 20;

create table t2
as
select rownum col1
,      case when mod(rownum,2) = 0 then 2 else 1 end col3
from   dual
connect by rownum <= 10;

select *
from   t1
,      t2
where  t1.col1 = t2.col1 (+) 
and  ((t1.col2 = 1
and    t2.col3 (+) > t1.col3)
or    (t1.col2 = 2
and    t2.col3 (+) < t1.col3));

ORA-01719: outer join operator (+) not allowed in operand of OR or IN

ANSI SQL remedies this:

alter session tracefile_identifier = 'domlg1';
alter session set events 'trace[rdbms.SQL_Optimizer.*]';
select *
from   t1
left join t2
on    t1.col1 = t2.col1
and ((t1.col2 = 1
and   t2.col3 > t1.col3)
or   (t1.col2 = 2
and   t2.col3 < t1.col3));

alter session set events 'trace off';

But it comes at a price.

Note the execution plan:

----------------------------------------------------------------------------
| Id  | Operation           | Name | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------
|   0 | SELECT STATEMENT    |      |    20 |  1300 |    42   (0)| 00:00:01 |
|   1 |  NESTED LOOPS OUTER |      |    20 |  1300 |    42   (0)| 00:00:01 |
|   2 |   TABLE ACCESS FULL | T1   |    20 |   780 |     2   (0)| 00:00:01 |
|   3 |   VIEW              |      |     1 |    26 |     2   (0)| 00:00:01 |
|*  4 |    TABLE ACCESS FULL| T2   |     1 |    26 |     2   (0)| 00:00:01 |
----------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   4 - filter("T1"."COL1"="T2"."COL1" AND ("T1"."COL2"=1 AND
              "T2"."COL3">"T1"."COL3" OR "T1"."COL2"=2 AND "T2"."COL3"<"T1"."COL3"))   

Now, maybe you will have better luck than me but no matter what I try I cannot change the NESTED LOOPS OUTER operation (I could rewrite it to do two joins rather than one and remove the OR).

So, if that lateral view involves some full table scans or other significant operations, they might be very expense on the outer operation of a nested loop.

The reason is in the optimizer trace.

Query after View Removal
******* UNPARSED QUERY IS ********
SELECT "T1."COL1" "COL1", "T1."COL2" "COL2", "T1."COL3" "COL3", "VW_LAT_AE9E49E8"."ITEM_1_0" "COL1", "VW_LAT_AE9E49E8"."ITEM_2_1" "COL3" FROM "DOM"."T1" "T1", LATERAL( (SELECT "T2"."COL1" "ITEM_1_0", "T2"."COL3" "ITEM_2_1" FROM "DOM"."T2" "T2" WHERE "T1"."COL1"="T2"."COL1" AND ("T1"."COL2"=1 AND "T2"."COL3">"T1"."COL3" OR "T1"."COL2"=2 AND "T2"."COL3" < "T1"."COL3"))) (+) "VW_LAT_AE9E49E8"
DCL:Checking validity of lateral view decorrelation SEL$BCD4421C (#1)
DCL: Bypassed: view has non-well-formed predicate
DCL: Failed decorrelation validity for lateral view block SEL$BCD4421C (#1)

The OR prevents the decorrelation which seems to mean that we’re stuck with a NESTED LOOP for now.

Further Reading on ANSI:
Oracle Optimizer Blog
Jonathan Lewis on ANSI Outer
Jonathan Lewis on ANSI

INSERT ALL caveat

Why you might want to think twice about using INSERT ALL.

One of those things I knew and then forgot.

So, let’s say you’ve got three tables or a partitioned table or something like that.

Let’s use regional tables for simplicity.

drop table t1_r1;
drop table t1_r2;
drop table t1_r3;

create table t1_r1
(col1 varchar2(2) not null
,col2 number not null
,check( col1 in ('R1')));

create table t1_r2
(col1 varchar2(2) not null
,col2 number not null
,check( col1 in ('R2')));

create table t1_r3
(col1 varchar2(2) not null
,col2 number not null
,check( col1 in ('R3')));

insert into t1_r1 values ('R1',1);
insert into t1_r2 values ('R2',1);
insert into t1_r3 values ('R3',1);

commit;

And you want a routine that will insert into one of those tables depending on region.

And you’re a simple fellow, so you go with an IF statement:

create or replace procedure p1 (
  col1 in varchar2, 
  col2 in number
)
as
begin
  if col1 = 'R1'
  then
      insert into t1_r1 values(col1,col2);
  elsif col1 = 'R2'
  then
      insert into t1_r3 values(col1,col2);
  else 
      insert into t1_r3 values(col1,col2);
  end if;
end p1;
/

Procedure P1 compiled

And then in the same session you run this uncommitted:

exec p1('R1',2);

PL/SQL procedure successfully completed.

And then in another session you decide to truncate table T1_R3:

truncate table t1_r3;

Table T1_R3 truncated.

No problem.
None was expected.

However…

Let’s say that we decide to tidy up that procedure and get rid of some of the repetition by using an INSERT ALL statement.
I will use a standalone sql statement just to demonstrate a further minor aspect rather than using a procedure with a bound parameter.

insert all
when col1 = 'R1' then into t1_r1
when col1 = 'R2' then into t1_r2
when col1 = 'R3' then into t1_r3
select 'R1' col1,2 col2
from dual;

1 row inserted.

Let’s revisit the truncate:

truncate table t1_r3;

SQL Error: ORA-00054: resource busy and acquire with NOWAIT specified or timeout expired
00054. 00000 -  "resource busy and acquire with NOWAIT specified or timeout expired"
*Cause:    Interested resource is busy.
*Action:   Retry if necessary or increase timeout.

TM share locks from the INSERT ALL on all three possible targets prevent the TRUNCATE.

So, a simple/simplisitic illustration of why you might want to think twice about whether INSERT ALL is the best feature for your use case, based on a real life problem.

Side-effect of ALTER SESSION SET CURRENT_SCHEMA

For most of our database set-ups we use a different TEMP space for application users than for end-user/support/developer/reporting usage.
The intention is to minimise the potential impact of a rogue ad-hoc query on the main applicaiton.

However, turns out this is ineffective IF you use:

ALTER SESSION SET CURRENT_SCHEMA = main_app_schema;

This is documented but I wasn’t previously aware.
No surprise that this learning opportunity was presented as a direct result of a rogue query on a prod DB blowing out the main TEMP space.

Deduction quickly suggested that the above must be the case and it was quickly proven by a test case and also supported by the documentation .

the database uses the temporary tablespace of the specified schema for sorts, joins, and storage of temporary database objects

Obviously… not using ALTER SESSION and using fully qualified object names prevents this “vulnerability”… but that’s not good enough unfortunately.

Did it really fix it 2: Plan flip, unprofileable, baseline OFE round 2 and “stability”

Snappy title, huh?

Aka: Why a sql plan baseline may be no guarantee of stability.

The other day, a problematic plan flip…

Tangent 1:
Cue much discussion about plan flips etc.
My thoughts on stability are that the priority for most application owners is stability and predictability but that does not tally with the defaul CBO behaviour and potentially you have to turn off a helluva lot to even get close.

Tangent 2:
I have commented before about the common sensitive of many databases to concurrent direct path reads (or rather the sensitivity is on the underlying SAN).

Here is one such illustration caused by this particular plan flip.

See that our single block read times go out from a “normal” range of 5 – 20ms to an average of 50+ ms. At this point anything doing physical IO starts to notice.
(Needless to say, I’m not a fan of these “normal” IO times – I think they’re awful but the SLA of the tier 2 (non flash) SAN storage is 20ms so we don’t alert until we breach that.)
sbr

Source:

select snap_id, begin_time, end_time, round(average,2)
from   dba_hist_sysmetric_summary
where  metric_name     = 'Average Synchronous Single-Block Read Latency'
order by snap_id;

Back to reality
Anyway, standard immediate-term fix for a plan flip is to hunt down a better plan from AWR and fix it with a profile or a baseline.

Not a problem to find one for this SQL as it nearly always executed with the same decent plan.
(AWR history is much longer than this but it gives the picture)

select to_char(trunc(sn.end_interval_time),'DD-MON-YYYY') dt
,      st.sql_id
,      st.plan_hash_value
,      sum(rows_processed_delta) rws
,      sum(executions_delta)     execs
,      round(sum(elapsed_time_delta)/1000/1000)   elp
,      round(sum(elapsed_time_delta)/1000/1000/nvl(nullif(sum(executions_delta),0),1),2)   elpe
,      round(sum(iowait_delta)/1000/1000)         io
,      round(sum(cpu_time_delta)/1000/1000)       cpu
,      sum(buffer_gets_delta)    gets
,      round(sum(disk_reads_delta))         disk_reads
from   dba_hist_snapshot sn
,      dba_hist_sqlstat  st
where  st.snap_id            = sn.snap_id
and    sn.instance_number = st.instance_number
and    st.sql_id             IN ('6xrx006fmqbq2')
group by trunc(sn.end_interval_time), st.sql_id, st.plan_hash_value
order by trunc(sn.end_interval_time) desc, elp desc; 
DT          SQL_ID        PLAN_HASH_VALUE        RWS      EXECS        ELP       ELPE         IO        CPU       GETS DISK_READS
----------- ------------- --------------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ----------
10-NOV-2015 6xrx006fmqbq2      3871506300          5       1815     236211     130.14     226340       9993  757853211  745588219 
09-NOV-2015 6xrx006fmqbq2      3871506300          1       1232     156412     126.96     149660       6846  507571690  499305166 
09-NOV-2015 6xrx006fmqbq2      3803735407         53       6835        743        .11          3        723  190488567         41 
07-NOV-2015 6xrx006fmqbq2      3803735407         31       3079        230        .07          3        218   37385043         56 
06-NOV-2015 6xrx006fmqbq2      3803735407        166      18931       1200        .06         11       1128  180142678        484 
05-NOV-2015 6xrx006fmqbq2      3803735407        305       9904        553        .06          5        508   75239139         93 
04-NOV-2015 6xrx006fmqbq2      3803735407        160      18900       1089        .06          9       1027  150523728        204 
03-NOV-2015 6xrx006fmqbq2      3803735407        226      12048        859        .07         58        794  154111239        424 
02-NOV-2015 6xrx006fmqbq2      3803735407       1081      13327       1276         .1         66       1200  278129234        465 

Problem plan is obvious, right?

Started during the day on the 9th, continued overnight until eventually noticed.

PHV 3871506300 does a FTS and gets direct path reads which causes our IO stress.

So, as mentioned, no problem, hint it with a sql profile via COE_XFR_SQL_PROFILE.sql (see Metalink note 215187.1)

But it didn’t work.

Not properly.

See top line.

DT          SQL_ID        PLAN_HASH_VALUE        RWS      EXECS        ELP       ELPE         IO        CPU       GETS DISK_READS
----------- ------------- --------------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ----------
10-NOV-2015 6xrx006fmqbq2      3353364157         20       4485     114084      25.44          4     111246 2907305774        216
10-NOV-2015 6xrx006fmqbq2      3871506300          5       1815     236211     130.14     226340       9993  757853211  745588219 
09-NOV-2015 6xrx006fmqbq2      3871506300          1       1232     156412     126.96     149660       6846  507571690  499305166 
09-NOV-2015 6xrx006fmqbq2      3803735407         53       6835        743        .11          3        723  190488567         41 
07-NOV-2015 6xrx006fmqbq2      3803735407         31       3079        230        .07          3        218   37385043         56 
06-NOV-2015 6xrx006fmqbq2      3803735407        166      18931       1200        .06         11       1128  180142678        484 
05-NOV-2015 6xrx006fmqbq2      3803735407        305       9904        553        .06          5        508   75239139         93 
04-NOV-2015 6xrx006fmqbq2      3803735407        160      18900       1089        .06          9       1027  150523728        204 
03-NOV-2015 6xrx006fmqbq2      3803735407        226      12048        859        .07         58        794  154111239        424 
02-NOV-2015 6xrx006fmqbq2      3803735407       1081      13327       1276         .1         66       1200  278129234        465 

We didn’t get “good” plan PHV 3803735407, we avoided “nasty” plan PHV 3871506300 but we got not-quite-so-nasty-but-still-not-nice PHV 3353364157.

The SQL Profile was not able to reproduce the desired PHV.

But at least PHV was not doing the problematic direct path reads!

I took the hints from PHV 3803735407 via

select * from table(dbms_xplan.display_awr('6xrx006fmqbq2',3803735407,format=>'+OUTLINE'));

I double checked they matched the hints in the SQL Profile – they did.

I tried using the hints manually in a SQL statement and the result was consistent with the SQL Profile – PHV 3353364157.

At this point, the DBA suggested using a SQL Plan Baseline.

I resisted but eventually gave in.

Why would it make any difference?

When a plan cannot be reproduced then there are good reasons why a baseline is much, much safer than a profile.

A baseline must reproduce the desired PHV or it will be rejected completely.

A profile has no knowledge of PHV so it is possible that under certain circumstances the hints in a profile may be only partially applied.

Profile was dropped and baseline was created.

This was the immediate aftermath (top line)… Success!

And V$SQL was showing that the baseline was being used.

DT          SQL_ID        PLAN_HASH_VALUE        RWS      EXECS        ELP       ELPE         IO        CPU       GETS DISK_READS
----------- ------------- --------------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ----------
10-NOV-2015 6xrx006fmqbq2      3803735407          4       1866        120        .06          1        116   17401768         30 
10-NOV-2015 6xrx006fmqbq2      3353364157         20       4485     114084      25.44          4     111246 2907305774        216
10-NOV-2015 6xrx006fmqbq2      3871506300          5       1815     236211     130.14     226340       9993  757853211  745588219 
09-NOV-2015 6xrx006fmqbq2      3871506300          1       1232     156412     126.96     149660       6846  507571690  499305166 
09-NOV-2015 6xrx006fmqbq2      3871506300          1       1232     156412     126.96     149660       6846  507571690  499305166 
09-NOV-2015 6xrx006fmqbq2      3803735407         53       6835        743        .11          3        723  190488567         41 
07-NOV-2015 6xrx006fmqbq2      3803735407         31       3079        230        .07          3        218   37385043         56 
06-NOV-2015 6xrx006fmqbq2      3803735407        166      18931       1200        .06         11       1128  180142678        484 
05-NOV-2015 6xrx006fmqbq2      3803735407        305       9904        553        .06          5        508   75239139         93 
04-NOV-2015 6xrx006fmqbq2      3803735407        160      18900       1089        .06          9       1027  150523728        204 
03-NOV-2015 6xrx006fmqbq2      3803735407        226      12048        859        .07         58        794  154111239        424 
02-NOV-2015 6xrx006fmqbq2      3803735407       1081      13327       1276         .1         66       1200  278129234        465 

I maintained that this didn’t make sense but the ticket was closed so I couldn’t get an SPM trace.

At this point a copy of the statement without profile and without baseline and without the manual fullset of hints was returning the original PHV 3803735407.

I went away that night and on the train I had a thought: “what if it wasn’t round 1 of the baseline which worked but round 2”.

Reminder of the baseline reproduction system

Round 2 is OFE only.

Doesn’t matter whether it is round 1 or round 2, if it’s reproduced it’s reproduced.

But if it was under OFE only then that was no guarantee of stability.

Then the following night, late night call, the baseline was no longer reproducing PHV 3803735407 but was back to the big problem PHV 3871506300!

Although I didn’t have an SPM trace, I’m adamant it verified my theory about it being round 2 only.

DT          SQL_ID        PLAN_HASH_VALUE        RWS      EXECS        ELP       ELPE         IO        CPU       GETS DISK_READS
----------- ------------- --------------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ----------
11-NOV-2015 6xrx006fmqbq2      3871506300          0        471      80513     170.94      77936       2543  193096137  188992511 
11-NOV-2015 6xrx006fmqbq2      3803735407        212       9933        690        .07         14        586   97253038        154 
10-NOV-2015 6xrx006fmqbq2      3803735407          4       1866        120        .06          1        116   17401768         30 
10-NOV-2015 6xrx006fmqbq2      3353364157         20       4485     114084      25.44          4     111246 2907305774        216
10-NOV-2015 6xrx006fmqbq2      3871506300          5       1815     236211     130.14     226340       9993  757853211  745588219 
09-NOV-2015 6xrx006fmqbq2      3871506300          1       1232     156412     126.96     149660       6846  507571690  499305166 
09-NOV-2015 6xrx006fmqbq2      3871506300          1       1232     156412     126.96     149660       6846  507571690  499305166 
09-NOV-2015 6xrx006fmqbq2      3803735407         53       6835        743        .11          3        723  190488567         41 
07-NOV-2015 6xrx006fmqbq2      3803735407         31       3079        230        .07          3        218   37385043         56 
06-NOV-2015 6xrx006fmqbq2      3803735407        166      18931       1200        .06         11       1128  180142678        484 
05-NOV-2015 6xrx006fmqbq2      3803735407        305       9904        553        .06          5        508   75239139         93 
04-NOV-2015 6xrx006fmqbq2      3803735407        160      18900       1089        .06          9       1027  150523728        204 
03-NOV-2015 6xrx006fmqbq2      3803735407        226      12048        859        .07         58        794  154111239        424 
02-NOV-2015 6xrx006fmqbq2      3803735407       1081      13327       1276         .1         66       1200  278129234        465 

Note that at times of change, no database structures were being changed.
Stats will have been gathered, sure – that was the agent of change no doubt.
But no index maintenance was happening, nothing was going unusable, no partition maintenance was happening.
Nothing was changing which should mean that a particular plan was impossible.

This means that the set of hints for this particular plan was not deterministic or rather the hintset was surely incomplete in some way which mean that the optimizer was free to do certain transformations which meant that the hintset was then invalid? Not 100% sure, still to be looked at in more detail…

At this point we dropped the baseline and went with a cut-down sql profile which applied only two hints – to politely request index scans for the two problematic FTS in each of PHV 3871506300 and 3353364157.

And this worked and has been ok since (so far) but it will not be the longer term solution.

DT          SQL_ID        PLAN_HASH_VALUE        RWS      EXECS        ELP       ELPE         IO        CPU       GETS DISK_READS
----------- ------------- --------------- ---------- ---------- ---------- ---------- ---------- ---------- ---------- ----------
16-NOV-2015 6xrx006fmqbq2      3803735407         80       6887        348        .05         11        310   44574494         86 
13-NOV-2015 6xrx006fmqbq2      3803735407        114      13054        842        .06         19        713  117260543        482 
12-NOV-2015 6xrx006fmqbq2      3803735407        585      28074       1854        .07         12       1823  321890748       1983 
11-NOV-2015 6xrx006fmqbq2      3871506300          0        471      80513     170.94      77936       2543  193096137  188992511 
11-NOV-2015 6xrx006fmqbq2      3803735407        212       9933        690        .07         14        586   97253038        154 
10-NOV-2015 6xrx006fmqbq2      3871506300          5       1815     236211     130.14     226340       9993  757853211  745588219 
10-NOV-2015 6xrx006fmqbq2      3353364157         20       4485     114084      25.44          4     111246 2907305774        216 
10-NOV-2015 6xrx006fmqbq2      3803735407          4       1866        120        .06          1        116   17401768         30 
09-NOV-2015 6xrx006fmqbq2      3871506300          1       1232     156412     126.96     149660       6846  507571690  499305166 
09-NOV-2015 6xrx006fmqbq2      3803735407         53       6835        743        .11          3        723  190488567         41 
07-NOV-2015 6xrx006fmqbq2      3803735407         31       3079        230        .07          3        218   37385043         56 
06-NOV-2015 6xrx006fmqbq2      3803735407        166      18931       1200        .06         11       1128  180142678        484 
05-NOV-2015 6xrx006fmqbq2      3803735407        305       9904        553        .06          5        508   75239139         93 
04-NOV-2015 6xrx006fmqbq2      3803735407        160      18900       1089        .06          9       1027  150523728        204 
03-NOV-2015 6xrx006fmqbq2      3803735407        226      12048        859        .07         58        794  154111239        424 
02-NOV-2015 6xrx006fmqbq2      3803735407       1081      13327       1276         .1         66       1200  278129234        465

Never before seen an execution plan which had quite this problem interacting with SPM.

A test case to get to the root of the problem is still on the TODO list.

Something to do with a statement involving a WITH subquery and NO_MERGE
e.g.

WITH x AS (SELECT /*+ no_merge...)
SELECT 
FROM ...
WHERE EXISTS (SELECT
              FROM   x
              ...
              WHERE...);