Adpative cursor sharing and row source statistics anomaly

Recently when playing with adaptive cursor sharing i observed a strange behavior when activating the row source statistics.Here is a quick test case to demonstrate the finding : (Tested database 11.2.0.3.9 and 12.1.0.2)

NOTE : The test done in this demonstration are from version 11.2.0.3.9 because V$SQL_CS_STATISTICS (the value that it display will help us understand what’s going on)  is for some reason empty in 12.1.0.2 .

I begin by creating a table with highly skewed data on record_type  (i used the example from Tim Hall and modified it)

  • Value 2 repeated 499 times
  • value 3 repeated 50002 times
  • all others repeated 2 times

DROP TABLE acs_test_tab;

CREATE TABLE acs_test_tab (
  id          NUMBER,
  record_type NUMBER,
  description VARCHAR2(50)
);

CREATE INDEX acs_test_tab_record_type_i ON acs_test_tab(record_type);

DECLARE
  TYPE t_acs_test_tab IS TABLE OF acs_test_tab%ROWTYPE;
  l_tab t_acs_test_tab := t_acs_test_tab();
 
BEGIN
  FOR i IN 1 .. 999 LOOP
    l_tab.extend;
    IF MOD(i,2)=0 THEN
      l_tab(l_tab.last).record_type := 2;
    ELSE
      l_tab(l_tab.last).record_type := i;
    END IF;
    
    l_tab(l_tab.last).id          := i;
    l_tab(l_tab.last).description := ‘Description for ‘ || i;
  END LOOP;

  FORALL i IN l_tab.first .. l_tab.last
    INSERT INTO acs_test_tab VALUES l_tab(i);

  COMMIT;
END;

DECLARE
  TYPE t_acs_test_tab IS TABLE OF acs_test_tab%ROWTYPE;
  l_tab t_acs_test_tab := t_acs_test_tab();
 
BEGIN
  FOR i IN 1 .. 100000 LOOP
    l_tab.extend;
    IF MOD(i,2)=0 THEN
      l_tab(l_tab.last).record_type := 3;
    ELSE
      l_tab(l_tab.last).record_type := i;
    END IF;
    
    l_tab(l_tab.last).id          := i;
    l_tab(l_tab.last).description := ‘Description for ‘ || i;
  END LOOP;

  FORALL i IN l_tab.first .. l_tab.last
    INSERT INTO acs_test_tab VALUES l_tab(i);

  COMMIT;
END;

EXEC DBMS_STATS.gather_table_stats(USER, ‘acs_test_tab’, method_opt=>’for all indexed columns size skewonly’, cascade=>TRUE);

And then i execute this series of query :

variable v number;
exec :v := 2;
select   /*+ anom2 */ max(id) from ACS_TEST_TAB where record_type = :v;
exec :v := 3;
select   /*+ anom2 */ max(id) from ACS_TEST_TAB where record_type = :v;
exec :v := 2;
select   /*+ anom2 */ max(id) from ACS_TEST_TAB where record_type = :v;
exec :v := 3;
select   /*+ anom2 */ max(id) from ACS_TEST_TAB where record_type = :v;

Without row source statistics  :

capture-1

The cursor is marked bind sensitive and the first execution was placed on the first bucket because it has processed 999 rows.As Carlos Sierra stated (http://carlos-sierra.net/2013/03/29/how-a-cursor-becomes-bind-aware/): “Observations on a test case built on 11.2.0.3 seem to indicate that boundaries for these 3 buckets are: less than 1,000; between 1,000 and 1,000,000; and more than 1,000,000.” it seem also that this boundary are still valid on 12.1.0.2 version.

capture-2

The second execution which processed far more rows is placed in the second bucket.

capture-3

The third execution marked the cursor bind aware.For information on when a cursor is marked bind aware please take look at Mohamed Houri Blog

capture-4

We can now see that a new plan was generated for the far less selective value.

With row source statistics  :

Now i will repeat the same test after enabling session tracing.

capture-10

Woww ! The rows_processed is now 1998 double the previous size (999 * 2 ) and the execution was placed in the second bucket (> 1000 ).The collection of row source statistics is some how influencing the measure used by adaptive cursor sharing.And in this case as you can see in the next screen shot the cursor will not be marked bind aware and will continue to use the same execution plan.(This sound very buggy to me.)

capture-11

That’s it 😀

6 thoughts on “Adpative cursor sharing and row source statistics anomaly

  1. Mahmoud

    v$sql_cs_statistics seems to be kept in 12c only for backward compatibility and is not maintained anymore
    Here’s below a spinet of what I wrote about this view in an upcoming book I am co-authoring

    “This view lists the statistics of the number of processed rows by the corresponding child cursor
    ,the number of executions it has undergone so far, and number of consumed buffers and CPU time.
    While this view was reporting something in 11g it seems not used anymore by Oracle starting from 12c as far as very often I have seen no rows in it when investigating the bind aware secret sauce in 12c. Even in 11g the number of rows processed was not updated before a cursor is bind aware”

    I have played with my test cases under 12c and have not reproduced this A-Rows doubling

    
    SQL> print:ln2
    
           LN2
    ----------
          1000
    
    SQL> select count(1) from t_acs where n2 = :ln2;
    
      COUNT(1)
    ----------
          1000
    
    SQL> select * from v$sql_cs_histogram where sql_id ='f2pmwazy1rnfd';
    
    ADDRESS          HASH_VALUE SQL_ID        CHILD_NUMBER  BUCKET_ID      COUNT     CON_ID
    ---------------- ---------- ------------- ------------ ---------- ---------- ----------
    00007FF9FFA53F30 4229681613 f2pmwazy1rnfd            0          0          0          1
    00007FF9FFA53F30 4229681613 f2pmwazy1rnfd            0          1          1          1
    00007FF9FFA53F30 4229681613 f2pmwazy1rnfd            0          2          0          1
    
    SQL> @46on 12
    
    Session altered.
    
    SQL> select count(1) from t_acs where n2 = :ln2;
    
      COUNT(1)
    ----------
          1000
    
    SQL> select * from table(dbms_xplan.display_cursor(null,null, 'allstats last'));
    
    
    SQL_ID  f2pmwazy1rnfd, child number 0
    -------------------------------------
    select count(1) from t_acs where n2 = :ln2
    
    Plan hash value: 1882749816
    
    ----------------------------------------------------------------------------------------
    | Id  | Operation         | Name     | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
    ----------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT  |          |      1 |        |      1 |00:00:00.01 |       5 |
    |   1 |  SORT AGGREGATE   |          |      1 |      1 |      1 |00:00:00.01 |       5 |
    |*  2 |   INDEX RANGE SCAN| T_ACS_I1 |      1 |   1070 |   1000 |00:00:00.01 |       5 |
    ----------------------------------------------------------------------------------------
    
    Predicate Information (identified by operation id):
    ---------------------------------------------------
    
       2 - access("N2"=:LN2)
       
    SQL> select * from v$sql_cs_histogram where sql_id ='f2pmwazy1rnfd';
    
    ADDRESS          HASH_VALUE SQL_ID        CHILD_NUMBER  BUCKET_ID      COUNT     CON_ID
    ---------------- ---------- ------------- ------------ ---------- ---------- ----------
    00007FF9FFA53F30 4229681613 f2pmwazy1rnfd            0          0          0          1
    00007FF9FFA53F30 4229681613 f2pmwazy1rnfd            0          1          2          1
    00007FF9FFA53F30 4229681613 f2pmwazy1rnfd            0          2          0          1
    

    Best regards
    Mohamed Houri
    http://www.hourim.wordpress.com

    • Hi Mohamed,

      First Thanks for the clarification about v$sql_cs_statistics view and I’m impatient to read your book :). I think you might have misunderstood me, i was talking about the effect of row source statistics on the calculation of “rows_processed” in v$sql_cs_statistics and not the A-ROWS.The example i have done is specifically designed that the first execution (value = 2 ) fall in the first bucket without row source statistics and in the second bucket when activating row source statistics caused by the increase in the value of “rows_processed” column > 1000. This same anomaly appear in 12.1.0.2 as i have tested the execution will fall in the second bucket and not the first so the row source statistics is some how influencing the measure used by adaptive cursor sharing. Can you please try the example in this post ?

    • Here is simpler example in 12.1.0.2 that show when activating row source statistics the execution will fall this time in second bucket :

      hatem>  variable v number;
      hatem> exec :v := 2;
      
      ProcÚdure PL/SQL terminÚe avec succÞs.
      
      hatem>  select   /*+ anom4 */ max(id) from ACS_TEST_TAB where record_type = :v;
      
         MAX(ID)
      ----------
             998
      
      1 ligne sÚlectionnÚe.
      
      hatem> select is_bind_sensitive,sql_id from v$sql where sql_text like '%anom4%';
      
      I SQL_ID
      - -------------
      N 0qc68a90503ju
      Y 1s1m0k0kzpf5j
      
      2 ligne(s) sÚlectionnÚe(s).
      
      hatem> select * from V$SQL_CS_HISTOGRAM where sql_id ='1s1m0k0kzpf5j';
      
      ADDRESS          HASH_VALUE SQL_ID        CHILD_NUMBER  BUCKET_ID      COUNT     CON_ID
      ---------------- ---------- ------------- ------------ ---------- ---------- ----------
      C000000B17F74680  637188273 1s1m0k0kzpf5j            0          0          1          0
      C000000B17F74680  637188273 1s1m0k0kzpf5j            0          1          0          0
      C000000B17F74680  637188273 1s1m0k0kzpf5j            0          2          0          0
      
      3 ligne(s) sÚlectionnÚe(s).
      
      hatem> exec dbms_monitor.session_trace_enable;
      
      ProcÚdure PL/SQL terminÚe avec succÞs.
      
      hatem>  select   /*+ anom4 */ max(id) from ACS_TEST_TAB where record_type = :v;
      
         MAX(ID)
      ----------
             998
      
      1 ligne sÚlectionnÚe.
      
      hatem> select * from V$SQL_CS_HISTOGRAM where sql_id ='1s1m0k0kzpf5j';
      
      ADDRESS          HASH_VALUE SQL_ID        CHILD_NUMBER  BUCKET_ID      COUNT     CON_ID
      ---------------- ---------- ------------- ------------ ---------- ---------- ----------
      C000000B17F74680  637188273 1s1m0k0kzpf5j            1          0          0          0
      C000000B17F74680  637188273 1s1m0k0kzpf5j            1          1          1          0
      C000000B17F74680  637188273 1s1m0k0kzpf5j            1          2          0          0
      C000000B17F74680  637188273 1s1m0k0kzpf5j            0          0          1          0
      C000000B17F74680  637188273 1s1m0k0kzpf5j            0          1          0          0
      C000000B17F74680  637188273 1s1m0k0kzpf5j            0          2          0          0
      
      6 ligne(s) sÚlectionnÚe(s).
      
      hatem@TRADIX> select * from v$version;
      
      BANNER                                                                               CON_ID
      -------------------------------------------------------------------------------- ----------
      Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production              0
      
      
  2. I would guess the doubling happens due to (a bug) related to the “qerst” / QUERY EXECUTION STATISTICS row source that gets injected between steps of your plan when _rowsource_execution_statistics=TRUE (these instrumentation plan lines do not show up in V$SQL_PLAN or explain plan output, but they are there).

  3. Hatem,

    Yes you are right. I have tested this for a different model and it behaves exactly as you’ve stated.

    Hopefully, ACS needs a couple of pre-requisites before kicking in. And according to my experience it causes more trouble than it solves.

    Particularly in real life cases taken from running systems where bind sensitive (and later bind aware) cursors have several predicates 4-8 for which there is always a room for a different set of bind variable selectivity that doesn’t fall into an existing child_number low-high range. In this case, the Extended Cursor Sharing layer code, which is responsible of peeking at this set of bind variable values for EACH execution, when a cursor is bind aware, will likely create a performance issue due to excessive parsing particularly when the underlying query is executed very frequently

    Best regards

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s