Tuesday, July 3, 2018

12c Online Statistics Gathering for Direct Path Insert and 3 Side Effects

Oracle 12c introduced Online Statistics Gathering for direct path Bulk Loads (CTAS and IAS), documented in:
    Online Statistics Gathering for Bulk Loads 
    Online Statistics Gathering 
This Blog will discuss its side effects in 3 aspects:
    Read Committed (default transaction isolation level)
    Global Temporary Table (GTT)
    Deadlock with MMON Slave Process (Mnnn)
Note: All tests are done in Oracle 12.1.0.2.0 and 12.2.0.1.0


1. Online Statistics Gathering


xplan is adjusted with one additional Row Source line marked as "OPTIMIZER STATISTICS GATHERING". And it is exposed in DBA_TAB_COL_STATISTICS.NOTES column as "STATS_ON_LOAD ".

SQL(100) > drop table test_tab;

SQL(100) > create table test_tab(x number, y number);

SQL(100) > explain plan for insert /*+ append */ into test_tab select level x, mod(level, 4) y from dual connect by level <= 4321;

SQL(100) > select * from table(dbms_xplan.display);

    ---------------------------------------------------------------------------------------
    Plan hash value: 1541388231
    
    -------------------------------------------------------------------------------------
    | Id  | Operation                        | Name     | Rows  | Cost (%CPU)| Time     |
    -------------------------------------------------------------------------------------
    |   0 | INSERT STATEMENT                 |          |     1 |     2   (0)| 00:00:01 |
    |   1 |  LOAD AS SELECT                  | TEST_TAB |       |            |          |
    |   2 |   OPTIMIZER STATISTICS GATHERING |          |     1 |     2   (0)| 00:00:01 |
    |*  3 |    CONNECT BY WITHOUT FILTERING  |          |       |            |          |
    |   4 |     FAST DUAL                    |          |     1 |     2   (0)| 00:00:01 |
    -------------------------------------------------------------------------------------

SQL(100) > insert /*+ append */ into test_tab select level x, mod(level, 4) y from dual connect by level <= 4321;

SQL(100) > select owner, table_name, column_name, num_distinct, last_analyzed, '"'||notes||'"'
           from dba_tab_col_statistics 
           where table_name in ('TEST_TAB') and notes like '%STATS_ON_LOAD%';

    OWNER  TABLE_NAME  COLUMN_NAME  NUM_DISTINCT  LAST_ANALYZED         NOTES
    ------ ----------- ------------ ------------- --------------------- ----------------
    K      TEST_TAB    X            4321          2018-JUL-03 08:08:09  "STATS_ON_LOAD "
    K      TEST_TAB    Y            4             2018-JUL-03 08:08:09  "STATS_ON_LOAD "

SQL(100) > commit;
Same as other new features, Oracle provided 3 ways to disable it:
    Statement level hints: 
        no_gather_optimizer_statistics
      or 
        OPT_PARAM('_optimizer_gather_stats_on_load' 'false') 
    Session level: 
        alter session set "_optimizer_gather_stats_on_load"=false;
    System level:
        alter system set "_optimizer_gather_stats_on_load"=false;


2. Read Committed Violation


At first, look the new behaviour of Read Committed as Oracle default transaction isolation level:

---========= (1-1): Session_1@T1 =========---
SQL(100) > drop table test_tab;

SQL(100) > create table test_tab(x number, y number);

SQL(100) > insert /*+ append */ into test_tab select level x, mod(level, 4) y from dual connect by level <= 4321;
    4321 rows created.

---========= (1-2): Session_2@T2 =========---
         
SQL(200) > select table_name, num_rows, last_analyzed from dba_tables where table_name in ('TEST_TAB');
    TABLE_NAME     NUM_ROWS LAST_ANALYZED
    ------------ ---------- --------------------
    TEST_TAB           4321 2018*JUN*29 10:52:41

SQL(200) > explain plan for select * from test_tab; 

SQL(200) > select * from table(dbms_xplan.display);

    ------------------------------------------------------------------------------
    | Id  | Operation         | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
    ------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT  |          |  4321 | 30247 |    30   (0)| 00:00:01 |
    |   1 |  TABLE ACCESS FULL| TEST_TAB |  4321 | 30247 |    30   (0)| 00:00:01 |
    ------------------------------------------------------------------------------      
       
---========= (1-3): Session_1@T3 =========---         
SQL(100) > rollback;

SQL(100) > insert /*+ append */ into test_tab select level x, mod(level, 4) y from dual connect by level <= 1234;
    1234 rows created.
             
---========= (1-4): Session_2@T4 =========---
SQL(200) > select table_name, num_rows, last_analyzed from dba_tables where table_name in ('TEST_TAB');
    TABLE_NAME     NUM_ROWS LAST_ANALYZED
    ------------ ---------- -------------
    TEST_TAB

SQL(200) > explain plan for select * from test_tab; 

SQL(200) > select * from table(dbms_xplan.display);

    ------------------------------------------------------------------------------
    | Id  | Operation         | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
    ------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT  |          |    82 |   574 |     2   (0)| 00:00:01 |
    |   1 |  TABLE ACCESS FULL| TEST_TAB |    82 |   574 |     2   (0)| 00:00:01 |
    ------------------------------------------------------------------------------
Above tests showed that the second session can see the exact number (4321) of inserted rows from first session before committed, hence "Read Committed" broken.

If rollback IAS and insert again, there is no more Online Statistics Gathering. So this feature is only waked up on the first IAS.

As a consequence, Xplan is created based on un-committed data, potentially volatile xplan and unstable performance.

Continue our test, if we truncate the table and insert again (also without commit), Online Statistics Gathering recurs again as demonstrated below:

---========= (1-5): Session_1@T5 =========---         

SQL(100) > truncate table test_tab;

SQL(100) > insert /*+ append */ into test_tab select level x, mod(level, 4) y from dual connect by level <= 9876;

---========= (1-6): Session_2@T6 =========---

SQL(200) > select table_name, num_rows, last_analyzed from dba_tables where table_name in ('TEST_TAB');
    TABLE_NAME     NUM_ROWS LAST_ANALYZED
    ------------ ---------- --------------------
    TEST_TAB           9876 2018*JUN*29 10:58:41

SQL(200) > explain plan for select * from test_tab; 

SQL(200) > select * from table(dbms_xplan.display);

    ------------------------------------------------------------------------------
    | Id  | Operation         | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
    ------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT  |          |  9876 | 69132 |     4   (0)| 00:00:01 |
    |   1 |  TABLE ACCESS FULL| TEST_TAB |  9876 | 69132 |     4   (0)| 00:00:01 |
    ------------------------------------------------------------------------------


3. Global Temporary Table


Repeat the same test for GTT with commit delete rows.

---========= (2-1): Session_1@T7 =========---         
SQL(100) > rollback;

SQL(100) > drop table test_tab;

SQL(100) > create global temporary table test_tab(x number, y number) on commit delete rows;  

SQL(100) > insert /*+ append */ into test_tab select level x, mod(level, 4) y from dual connect by level <= 4321;
    4321 rows created.


---========= (2-2): Session_2@T8 =========---
         
SQL(200) > select table_name, num_rows, last_analyzed from dba_tables where table_name in ('TEST_TAB');
    TABLE_NAME     NUM_ROWS LAST_ANALYZED
    ------------ ---------- --------------------
    TEST_TAB           4321 2018*JUN*29 11:19:36

SQL(200) > explain plan for select * from test_tab; 

SQL(200) > select * from table(dbms_xplan.display);

    ------------------------------------------------------------------------------
    | Id  | Operation         | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
    ------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT  |          |  4321 | 30247 |    30   (0)| 00:00:01 |
    |   1 |  TABLE ACCESS FULL| TEST_TAB |  4321 | 30247 |    30   (0)| 00:00:01 |
    ------------------------------------------------------------------------------      

---========= (2-3): Session_1@T9 =========---         
SQL(100) > rollback;

SQL(100) > insert /*+ append */ into test_tab select level x, mod(level, 4) y from dual connect by level <= 1234;
    1234 rows created.
             
---========= (2-4): Session_2@T10 =========---
SQL(200) > select table_name, num_rows, last_analyzed from dba_tables where table_name in ('TEST_TAB');
    TABLE_NAME     NUM_ROWS LAST_ANALYZED
    ------------ ---------- --------------------
    TEST_TAB           1234 2018*JUN*29 11:21:16

SQL(200) > explain plan for select * from test_tab; 

SQL(200) > select * from table(dbms_xplan.display);

    ------------------------------------------------------------------------------
    | Id  | Operation         | Name     | Rows  | Bytes | Cost (%CPU)| Time     |
    ------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT  |          |  1234 |  8638 |    30   (0)| 00:00:01 |
    |   1 |  TABLE ACCESS FULL| TEST_TAB |  1234 |  8638 |    30   (0)| 00:00:01 |
    ------------------------------------------------------------------------------
For GTT, other session can also see the exact number (4321) of inserted rows, hence GTT is no more session private.

In contrary to normal table, if rollback IAS and insert again, Online Statistics is re-gathered.

If GTT is created with commit preserve rows, the behavior is similar to normal table.

However Oracle 12c Documentation said that bulk loads do not gather statistics automatically when target table is global temporary table defined as ON COMMIT DELETE ROWS (see Online Statistics Gathering for Bulk Loads ).

The default GTT behaviour ('SHARED') can be turned off by global or table prefs:

exec dbms_stats.set_global_prefs ('GLOBAL_TEMP_TABLE_STATS','SESSION');
exec dbms_stats.set_table_prefs(null, 'TEST_TAB', 'GLOBAL_TEMP_TABLE_STATS', 'SESSION');

select dbms_stats.get_prefs('GLOBAL_TEMP_TABLE_STATS') from dual;


4. Internals


Turn on SQL Trace (10046), perform 3 IAS operations and one CTAS, trace files show the call of dbms_stats.postprocess_stats, which is probably gathering Online Statistics.

IAS - insert
  BEGIN dbms_stats.postprocess_stats(:owner, :tabname, :partname, :subpartname, 2, :rawstats, :selmap, :clist); END; 

IAS - commit
  BEGIN dbms_stats.postprocess_stats(:owner, :tabname, :partname, :subpartname, 1, null, null, null); END; 

IAS - rollback
  BEGIN dbms_stats.postprocess_stats(:owner, :tabname, :partname, :subpartname, 8, null, null, null); END; 

CTAS
  create table test_tab as select level x, mod(level, 4) y from dual connect by level <= 4321;
  BEGIN dbms_stats.postprocess_stats(:owner, :tabname, :partname, :subpartname, 6, :rawstats, :selmap, :clist);  END;   
It looks like that Statistics gathering is controlled by different FLAG (2, 1, 8, 6), where CTAS 6 = 2 + 4.

With dbms_stats Tracing, we can also observe this call:

SQL(300) > execute dbms_stats.set_global_prefs('trace',to_char(1+4+16+2048+65536)); 

SQL(300) > select sname, sval2, spare4 from sys.optstat_hist_control$ where sname in ('TRACE');
    SNAME      SVAL2                          SPARE4
    ---------- ------------------------------ ------
    TRACE      2018-JUN-29 12:10:36 +02:00    67605

SQL(300) > drop table test_tab;
SQL(300) > create table test_tab as select level x, mod(level, 4) y from dual connect by level <= 4321;

  DBMS_STATS: postprocess_stats on KS.TEST_TAB.. tobjn: 2585597 fobjn:
  DBMS_STATS: postprocess online optimizer stats gathering for KS.TEST_TAB: save statistics


5. Deadlock


There exist one background MMON Slave Process (Mnnn, for instance, M002), which is periodically (each 15 minutes in default) spawned to update Online Statistics (Flush KSXM hash table action). If coincidentally one foreground User session performs an IAS or CTAS operation at the same time, it can cause some deadlock as follows (some text removed):

Deadlock graph:
                ---------Blocker(s)--------  ---------Waiter(s)---------
Resource Name   process session holds waits  process session holds waits
TX-001F0003     123     321     X            789    987      S
TX-004C0008     789     987     X            123    321      X

Rows waited on:
  Session 321: obj - rowid = 00000001 
  (dictionary objn - 1, file - 51, block - 2012345, slot - 0)
  Session 987: no row
 
----- Information for the OTHER waiting sessions -----
Session 987:
  sid: 987 ser: 9876 audsid: 0 user: 0/SYS
    image: oracle@testdb (M002)
  current SQL:
    merge /*+ dynamic_sampling(mm 4) dynamic_sampling_est_cdn(mm) dynamic_sampling(m 4) dynamic_sampling_est_cdn(m) */ into sys.mon_mods_all$ mm
 
Information for THIS session:
----- Current SQL Statement for this session (sql_id=cyz7q9n00p23a) -----
update optstat_hist_control$ set sval2 = systimestamp  where sname = 'MON_MODS_ALL_UPD_TIME'   
If we turn on following sql_trace:

alter system set events 'sql_trace [sql:5vf82wpjq5y0v] wait=true, bind=true,plan_stat=first_execution,level=12';

alter system set events 'sql_trace [sql:cyz7q9n00p23a] wait=true, bind=true,plan_stat=first_execution,level=12';

alter system set events 'sql_trace [sql:aahsjvcnr3swn] wait=true, bind=true,plan_stat=first_execution,level=12';
and look both trace files (see Appendix: sql_fulltext):

Unix process pid: 123, image: oracle@testdb (M002)
  *** ACTION NAME:(Flush KSXM hash table action) 2018-06-26 11:15:27.632
 
===================== sql_id=5vf82wpjq5y0v 
select null from optstat_hist_control$ 
where sname = 'MON_MODS_ALL_UPD_TIME' 
  and ((systimestamp - sval2) > INTERVAL '540' SECOND or sval2 is null)
for update

===================== sql_id=aahsjvcnr3swn
merge /*+ dynamic_sampling(mm 4) dynamic_sampling_est_cdn(mm) ynamic_sampling(m 4) dynamic_sampling_est_cdn(m) */                    
 into sys.mon_mods_all$ mm 
 
===================== sql_id=cyz7q9n00p23a 
update optstat_hist_control$ 
   set sval2 = systimestamp where sname = 'MON_MODS_ALL_UPD_TIME'

Unix process pid: 456, image: oracle@testdb

===================== sql_id=aahsjvcnr3swn
merge /*+ dynamic_sampling(mm 4) dynamic_sampling_est_cdn(mm) ynamic_sampling(m 4) dynamic_sampling_est_cdn(m) */                    
 into sys.mon_mods_all$ mm 
 
===================== sql_id=cyz7q9n00p23a 
update optstat_hist_control$ 
   set sval2 = systimestamp where sname = 'MON_MODS_ALL_UPD_TIME'
The above trace files showed that M002 performs:
  select from optstat_hist_control$ for update
  merge into sys.mon_mods_all$
  update optstat_hist_control$ 
whereas User session executes:
  merge into sys.mon_mods_all$
  update optstat_hist_control$ 
The interleaved DML calls on mon_mods_all$ and optstat_hist_control$ probably caused the deadlock.

For all ORA-00060, the trace file is printed with following notice:
  The following deadlock is not an ORACLE error. It is a
  deadlock due to user error in the design of an application
  or from issuing incorrect ad-hoc SQL. The following
  information may aid in determining the deadlock:
In this case, the standard message is probably not addressed to application users.

Oracle has a hidden parameter (existed already in Oracle 11g):

   _dml_monitoring_enabled 
to toggle modification monitoring. The default value is TRUE, i.e. enabled.
The workaround could be:

   alter system set "_dml_monitoring_enabled"=false;
but MOS: "Bug 20559144 - DML Monitoring can only be disabled with STATISTICS_LEVEL (Doc ID 20559144.8)" said:
    dml monitoring is happens even with _dml_monitoring_enabled set to false
and futher Workaround is:

    statistics_level=basic
We have tested that only setting _dml_monitoring_enabled=false, and leaving statistics_level=typical dml monitoring still occurs. Once setting _dml_monitoring_enabled=false, and statistics_level=basic there is no more dml monitoring. These can be checked by reading MMON Slave Process (Mnnn) traces or running query below, and observing executions increasing, last_active_time progressing:
  
   select sql_id, executions, last_active_time, first_load_time, sql_text
   from v$sql v 
   where sql_id in ('5vf82wpjq5y0v', 'cyz7q9n00p23a', 'aahsjvcnr3swn')
   order by v.last_active_time desc;   


6. Appendix: sql_fulltext


Here the complete sqltext of above involved statements:

--sql_id=5vf82wpjq5y0v 
 select null
   from optstat_hist_control$
  where     sname = 'MON_MODS_ALL_UPD_TIME'
        and ( (systimestamp - sval2) > interval '540' second or sval2 is null)
 for update

--sql_id=cyz7q9n00p23a 
update sys.optstat_hist_control$ set sval2 = systimestamp  where sname = 'MON_MODS_ALL_UPD_TIME';

--sql_id=aahsjvcnr3swn  (M002)
merge /*+ dynamic_sampling(mm 4) dynamic_sampling_est_cdn(mm) dynamic_sampling(m 4) dynamic_sampling_est_cdn(m) */
     into  sys.mon_mods_all$ mm
     using (select m.obj#          obj#,
                   m.inserts       inserts,
                   m.updates       updates,
                   m.deletes       deletes,
                   m.flags         flags,
                   m.timestamp     timestamp,
                   m.drop_segments drop_segments
              from sys.mon_mods$ m, tab$ t
             where m.obj# = t.obj# and :objn = 0
            union all
            select m.obj#          obj#,
                   m.inserts       inserts,
                   m.updates       updates,
                   m.deletes       deletes,
                   m.flags         flags,
                   m.timestamp     timestamp,
                   m.drop_segments drop_segments
              from sys.mon_mods$ m, tab$ t
             where m.obj# = t.obj# and :objn > 0 and m.obj# = :objn) v
        on (mm.obj# = v.obj#)
when matched
then
  update set mm.inserts = mm.inserts + v.inserts,
             mm.updates = mm.updates + v.updates,
             mm.deletes = mm.deletes + v.deletes,
             mm.flags = mm.flags + v.flags - bitand (mm.flags, v.flags) /* bitor(mm.flags,v.flags) */,
             mm.timestamp = v.timestamp,
             mm.drop_segments = mm.drop_segments + v.drop_segments
when not matched
then
  insert     (obj#,
              inserts,
              updates,
              deletes,
              timestamp,
              flags,
              drop_segments)
      values (v.obj#,
              v.inserts,
              v.updates,
              v.deletes,
              sysdate,
              v.flags,
              v.drop_segments);