Tuesday, May 26, 2020

12cR2 Index Usage Tracking Manual Flushing

Oracle 12.2 introduced index usage tracking to replace the previous index monitoring. Instead of only telling if an index is used (DBA_OBJECT_USAGE.USED), usage tracking provides a quantified index usage stats, such as number of accesses, number of rows returned per access.

There are two views and 3 hidden parameters to report and control index usage tracking:
V$INDEX_USAGE_INFO 
  keeps track of index usage since the last flush. A flush occurs every 15 minutes. 
  After each flush, ACTIVE_ELEM_COUNT is reset to 0 and LAST_FLUSH_TIME is updated to the current time.
  
DBA_INDEX_USAGE 
  displays object-level index usage once it has been flushed to disk.
  
Hidden Parameters
  NAME                       DESCRIPTION                               DEFAULT
  -------------------------  ----------------------------------------  -------
  _iut_enable                Control Index usage tracking              TRUE
  _iut_max_entries           Maximum Index entries to be tracked       30000
  _iut_stat_collection_type  Specify Index usage stat collection type  SAMPLED
By default, index usage tracking is enable ("_iut_enable" = TRUE). To get an accurate result, switch collection type to ALL:

ALTER SYSTEM SET "_iut_stat_collection_type" = ALL;
This new feature is documented in Oracle MOS Docu and Oracle Blogs:
   -.  Index Monitoring in Oracle 12.2 (Doc ID 2302110.1)
   -. 12cR2 new index usage tracking
   -. Index Usage Tracking (DBA_INDEX_USAGE, V$INDEX_USAGE_INFO) in Oracle Database 12c Release 2 (12.2)

In this Blog, we first show how to manually flush usage data instead of waiting 15 minutes so that we can make a realtime index usage evaluation and more precisely locate index access.

Then we look how usage data are recorded by Oracle MMON Slave Process.

Note: Tested in Oracle 19c.


1. Test Setup


At first, create a table and a primary key index (TEST_IUT_PK) with 14 rows.

drop table test_iut purge;

create table test_iut(x, constraint TEST_IUT_PK primary key (x)) 
          as select level from dual connect by level <= 14;


2. Manual Flush


Open one Sqlplus session: SQL1, login as SYSDBA. Pick one MMON slave. for example, M001, attach oradebug on it.

$ > sqlplus / as sysdba

SQL1 > 
     select s.program, s.module, s.action, s.sid, p.pid, p.spid
     from v$session s, v$process p 
     where s.paddr=p.addr and s.program like '%(M0%' 
     order by s.program;

       PROGRAM                 MODULE      ACTION                         SID  PID  SPID
       ----------------------  ----------  -----------------------------  ---  ---  -----
       oracle@testdb (M001)  MMON_SLAVE  Intensive AutoTask Dispatcher  186   49  20894
       oracle@testdb (M002)  MMON_SLAVE  KDILM background CLeaNup       912   35  2097
       oracle@testdb (M003)  MMON_SLAVE  KDILM background CLeaNup       371    8  13060
       oracle@testdb (M004)  MMON_SLAVE  KDILM background EXEcution     722   34  27905
       oracle@testdb (M005)  MMON_SLAVE  Intensive AutoTask Dispatcher  370   56  29674

SQL1 > oradebug setorapid 49
         Oracle pid: 49, Unix process pid: 20894, image: oracle@testdb (M001)
Open second Sqlplus session as a test session.

Change collection type to "ALL" so that statistics are collected for each sql execution that has index access (Note "alter SESSION" is the same as "alter SYSTEM" for this hidden parameter).

Run a query using index "TEST_IUT_PK", v$index_usage_info is not flushed immediately, hence dba_index_usage returns no rows about this index.

SQL2 > alter session set "_iut_stat_collection_type"=all;

SQL2 > select sysdate, x from test_iut where x= 3;

  SYSDATE                       X
  -------------------- ----------
  2020*MAY*23 15:22:46          3

SQL2 > select sysdate, index_stats_enabled, index_stats_collection_type, active_elem_count, last_flush_time
       from v$index_usage_info;

  SYSDATE              INDEX_STATS_ENABLED INDEX_STATS_COLLECTION_TYPE ACTIVE_ELEM_COUNT LAST_FLUSH_TIME
  -------------------- ------------------- --------------------------- ----------------- --------------------
  2020*MAY*23 15:23:55                   1                           0                 1 2020*MAY*23 15:21:34

SQL2 > select sysdate, total_access_count,total_exec_count,total_rows_returned,last_used
       from dba_index_usage where name = 'TEST_IUT_PK';

  no rows selected
Go back to SQL1, make a function call to flush usage stats:

SQL1 > oradebug call keiut_flush_all
         Function returned 60089650
We can see the usage stats are updated immediately (instead of waiting 15 minutes for one of MMON slaves to perform it).

SQL2 > select sysdate, index_stats_enabled, index_stats_collection_type, active_elem_count, last_flush_time
       from v$index_usage_info;
      
  SYSDATE              INDEX_STATS_ENABLED INDEX_STATS_COLLECTION_TYPE ACTIVE_ELEM_COUNT LAST_FLUSH_TIME
  -------------------- ------------------- --------------------------- ----------------- --------------------
  2020*MAY*23 15:24:57                   1                           0                 1 2020*MAY*23 15:24:46
                  
SQL2 > select sysdate, total_access_count,total_exec_count,total_rows_returned,last_used
       from dba_index_usage where name = 'TEST_IUT_PK';
      
  SYSDATE              TOTAL_ACCESS_COUNT TOTAL_EXEC_COUNT TOTAL_ROWS_RETURNED LAST_USED
  -------------------- ------------------ ---------------- ------------------- --------------------
  2020*MAY*23 15:25:17                  1                1                   1 2020*MAY*23 15:24:46      
Repeat the same steps after gather table and index stats, usage data are also flushed immediately.

SQL2 > exec dbms_stats.gather_table_stats(user, 'TEST_IUT', cascade=> TRUE);

SQL1 > oradebug call keiut_flush_all
         Function returned 60089650

SQL2 > select sysdate, index_stats_enabled, index_stats_collection_type, active_elem_count, last_flush_time
       from v$index_usage_info;
 
  SYSDATE              INDEX_STATS_ENABLED INDEX_STATS_COLLECTION_TYPE ACTIVE_ELEM_COUNT LAST_FLUSH_TIME
  -------------------- ------------------- --------------------------- ----------------- --------------------
  2020*MAY*23 15:26:03                   1                           0                 1 2020*MAY*23 15:25:55

SQL2 > select sysdate, total_access_count,total_exec_count,total_rows_returned,last_used
       from dba_index_usage where name = 'TEST_IUT_PK';
 
  SYSDATE              TOTAL_ACCESS_COUNT TOTAL_EXEC_COUNT TOTAL_ROWS_RETURNED LAST_USED
  -------------------- ------------------ ---------------- ------------------- --------------------
  2020*MAY*23 15:26:35                  2                2                  15 2020*MAY*23 15:25:55
In fact, index stats is gathered by a query as follows:

-- SQL_ID:   b1xgfyhj1c1yn

SELECT /*+ opt_param('_optimizer_use_auto_indexes' 'on')   no_parallel_index(t, "TEST_IUT_PK")  dbms_stats 
           cursor_sharing_exact use_weak_name_resl dynamic_sampling(0) no_monitoring xmlindex_sel_idx_tbl 
           opt_param('optimizer_inmemory_aware' 'false') no_substrb_pad  no_expand index(t,"TEST_IUT_PK") */
       COUNT (*)                                                AS nrw,
       COUNT (DISTINCT sys_op_lbid (3309518, 'L', t.ROWID))     AS nlb,
       NULL                                                     AS ndk,
       sys_op_countchg (SUBSTRB (t.ROWID, 1, 15), 1)            AS clf
  FROM "K"."TEST_IUT" t
 WHERE "X" IS NOT NULL

Plan hash value: 3307217019
 
--------------------------------------------------------------------------------
| Id  | Operation        | Name        | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------
|   0 | SELECT STATEMENT |             |     1 |     3 |     1   (0)| 00:00:01 |
|   1 |  SORT GROUP BY   |             |     1 |     3 |            |          |
|   2 |   INDEX FULL SCAN| TEST_IUT_PK |    14 |    42 |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------

Hint Report (identified by operation id / Query Block Name / Object Alias):
Total hints for statement: 12 (U - Unused (1))
---------------------------------------------------------------------------
   0 -  STATEMENT
           -  opt_param('_optimizer_use_auto_indexes' 'on')
           -  opt_param('optimizer_inmemory_aware' 'false')
   1 -  SEL$1
           -  dynamic_sampling(0)
           -  no_expand
   2 -  SEL$1 / T@SEL$1
         U -  no_parallel_index(t, "TEST_IUT_PK")
           -  index(t,"TEST_IUT_PK")
Since it is a "INDEX FULL SCAN", 14 rows are returned, which is reflected in dba_index_usage columns:
  BUCKET_11_100_ACCESS_COUNT 
  BUCKET_11_100_ROWS_RETURNED
Here the output formatted vertically. Two accesses, the first returns 1 row, the second returns 14 rows, both are classified into two different histogram buckets.

select sysdate, total_access_count,total_exec_count,total_rows_returned,last_used,
       bucket_0_access_count, bucket_1_access_count,bucket_11_100_access_count,bucket_11_100_rows_returned
   from dba_index_usage where name = 'TEST_IUT_PK';

  SYSDATE                       : 23-may-2020 15:26:59
  TOTAL_ACCESS_COUNT            : 2
  TOTAL_EXEC_COUNT              : 2
  TOTAL_ROWS_RETURNED           : 15
  LAST_USED                     : 23-may-2020 15:25:55
  BUCKET_0_ACCESS_COUNT         : 0
  BUCKET_1_ACCESS_COUNT         : 1
  BUCKET_11_100_ACCESS_COUNT    : 1
  BUCKET_11_100_ROWS_RETURNED   : 14


3. Usage Statistics Update


Static Data Dictionary View DBA_INDEX_USAGE is based on table SYS.WRI$_INDEX_USAGE. In normal operation, each 15 minutes, one MMON slave is triggered to update WRI$_INDEX_USAGE with a merge statement looping over each index object as follows:

--- 5cu0x10yu88sw

MERGE INTO sys.wri$_index_usage iu
     USING DUAL
        ON (iu.obj# = :objn)
WHEN MATCHED
THEN
    UPDATE SET
        iu.total_access_count = iu.total_access_count + :ns,
        iu.total_rows_returned = iu.total_rows_returned + :rr,
        iu.total_exec_count = iu.total_exec_count + :ne,
        iu.bucket_0_access_count = iu.bucket_0_access_count + :nsh0,
        iu.bucket_1_access_count = iu.bucket_1_access_count + :nsh1,
        iu.bucket_2_10_access_count = iu.bucket_2_10_access_count + :nsh2_10,
        iu.bucket_2_10_rows_returned =
            iu.bucket_2_10_rows_returned + :nrh2_10,
        iu.bucket_11_100_access_count =
            iu.bucket_11_100_access_count + :nsh11_100,
        iu.bucket_11_100_rows_returned =
            iu.bucket_11_100_rows_returned + :nrh11_100,
        iu.bucket_101_1000_access_count =
            iu.bucket_101_1000_access_count + :nsh101_1000,
        iu.bucket_101_1000_rows_returned =
            iu.bucket_101_1000_rows_returned + :nrh101_1000,
        iu.bucket_1000_plus_access_count =
            iu.bucket_1000_plus_access_count + :nsh1000plus,
        iu.bucket_1000_plus_rows_returned =
            iu.bucket_1000_plus_rows_returned + :nrh1000plus,
        last_used = SYSDATE
WHEN NOT MATCHED
THEN
    INSERT     (iu.obj#,
                iu.total_access_count,
                iu.total_rows_returned,
                iu.total_exec_count,
                iu.bucket_0_access_count,
                iu.bucket_1_access_count,
                iu.bucket_2_10_access_count,
                iu.bucket_2_10_rows_returned,
                iu.bucket_11_100_access_count,
                iu.bucket_11_100_rows_returned,
                iu.bucket_101_1000_access_count,
                iu.bucket_101_1000_rows_returned,
                iu.bucket_1000_plus_access_count,
                iu.bucket_1000_plus_rows_returned,
                iu.last_used)
        VALUES ( :objn,
                :ns,
                :rr,
                :ne,
                :nsh0,
                :nsh1,
                :nsh2_10,
                :nrh2_10,
                :nsh11_100,
                :nrh11_100,
                :nsh101_1000,
                :nrh101_1000,
                :nsh1000plus,
                :nrh1000plus,
                SYSDATE)

--------------------------------------------------------------------------------------------------------
| Id  | Operation                       | Name                | E-Rows |E-Bytes| Cost (%CPU)| E-Time   |
--------------------------------------------------------------------------------------------------------
|   0 | MERGE STATEMENT                 |                     |        |       |     3 (100)|          |
|   1 |  MERGE                          | WRI$_INDEX_USAGE    |        |       |            |          |
|   2 |   VIEW                          |                     |        |       |            |          |
|   3 |    NESTED LOOPS OUTER           |                     |      1 |   287 |     3   (0)| 00:00:01 |
|   4 |     TABLE ACCESS FULL           | DUAL                |      1 |     2 |     2   (0)| 00:00:01 |
|   5 |     VIEW                        | VW_LAT_A18161FF     |      1 |   285 |     1   (0)| 00:00:01 |
|   6 |      TABLE ACCESS BY INDEX ROWID| WRI$_INDEX_USAGE    |      1 |    48 |     1   (0)| 00:00:01 |
|*  7 |       INDEX UNIQUE SCAN         | WRI$_INDEX_USAGE_PK |      1 |       |     1   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------------------
We can see that merge statement is using index: WRI$_INDEX_USAGE_PK, but there is no usage stats on it (probably usage stats of SYS indexes are not tracked).

SQL2 > select total_access_count,total_exec_count,total_rows_returned,last_used
       from dba_index_usage where name = 'WRI$_INDEX_USAGE_PK';

  no rows selected
To flush usage stats, one active MMON slave starts a run of ACTION named: [Index usage tracking statistics flush]. If runtime exceeded 180 seconds, time limit violation (MMON slave action policy violation) is detected, an ORA-12751 is raised.
  12751, 00000, "cpu time or run time policy violation"
  // *Document: NO
  // *Cause: A piece of code ran longer than it is supposed to
  // *Action: If this error persists, contact Oracle Support Services.
As some future enhancement, this technique can be further extended if we can specify tracking index name, time interval, user sessions.

By the way, Oracle is continuously augmenting performance usage stats by including more tracking areas controlled by hidden parameters:
  NAME                         DESCRIPTION                                 DEFAULT
  ---------------------------  ------------------------------------------  -------
  _iut_enable                  Control Index usage tracking                TRUE
  _optimizer_track_hint_usage  enable tracking of optimizer hint usage     TRUE     
  _db_hot_block_tracking       track hot blocks for hash latch contention  FALSE
For example, in above Oracle generated gather index statement (SQL_ID b1xgfyhj1c1yn), Xplan is extended with one Hint Report introduced in Oracle 19.3.3. It can be disabled by:

alter session set "_optimizer_track_hint_usage" = false;