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;

Monday, May 25, 2020

One "row cache lock" Test Case

"row cache lock" is an Oracle locking mechanisms to protect disk layer persistent data (e.g. 'sys.user$'), whereas "latch: row cache objects" to protect memory (cache) layer volatile data (e.g. 'dc_users').

To improve performance, disk stored meta data are cached in memory layer. For any modifications, "row cache lock" is requested to synchronize and maintain data integrity and consistency.

"row cache lock" is well documented in MOS Docu:
  WAITEVENT: "row cache lock" Reference Note (Doc ID 34609.1)
    Parameters:
     P1 = cache - ID of the dictionary cache 
     P2 = mode - Mode held 
     P3 = request - Mode requested 
    p1:
     SELECT cache#, type, parameter FROM v$rowcache WHERE cache# = &P1;
    P2 and P3:
      KQRMNULL 0   null mode - not locked
      KQRMS    3   share mode
      KQRMX    5   exclusive mode
      KQRMFAIL 10  fail to acquire instance lock
In this Blog, we will demonstrate "row cache lock" with one test case, and then make further investigation with different tracing methods.

Note: Tested in Oracle 12cR1

(In Oracle 12.2.0.1.0 (12cR2), "row cache mutex" replaced 12.1.0.2.0 (12cR1) "latch: row cache objects", see Blog: row cache mutex in Oracle 12.2.0.1.0 )


1. Test Setup


At first, we create a test user and a procedure to change its identification.

drop user test_user cascade;
create user test_user identified by 123;
grant create session, alter session, create any procedure to test_user;

------- login as test_user -------
sqlplus test_user/123@testdb

create or replace procedure alter_user(p_cnt number) as
begin
  for i in 1..p_cnt loop
    execute immediate 'alter user test_user identified by 123';
  end loop;
end;
/

-- exec alter_user(1e1);


2. Contention Test


As first test, open two Sqlplus execution sessions: SID1, SID2 by test_user. And also open one monitoing session SID3. In SID1 and SID2, run above created procedure:

SID1 (367) > exec alter_user(1e6);

SID2 (549) > exec alter_user(1e6);
In monitoring session SID3, we can observe the contention on "row cache lock".

SID3 > 
select sid, event, total_waits, total_timeouts, time_waited, average_wait, max_wait, time_waited_micro 
from v$session_event 
where event = 'row cache lock' or sid in (367, 549)
order by total_waits desc;

  SID EVENT                     TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT   MAX_WAIT TIME_WAITED_MICRO
  --- ------------------------- ----------- -------------- ----------- ------------ ---------- -----------------
  549 row cache lock                 844170              0      510871          .61          6        5108705693
  367 row cache lock                 842831              0      510068          .61          5        5100680960
  549 library cache: mutex X          51920              0       12591          .24          2         125907876
  367 library cache: mutex X          46584              0       10950          .24          2         109501712
  549 latch: row cache objects         5198              0          17            0          0            165028
  367 latch: row cache objects         4963              0          16            0          0            156902
  549 cursor: mutex X                  1920              0         420          .22          1           4202576
  367 cursor: mutex X                  1746              0         380          .22          1           3801026
  549 latch: shared pool               1496              0           4            0          0             43000
  367 latch: shared pool               1344              0           4            0          0             39746

select event, total_waits, total_timeouts, time_waited, average_wait 
      ,total_waits_fg, total_timeouts_fg, time_waited_fg, average_wait_fg
from v$system_event where lower(event) like '%row cache%';

  EVENT                     TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED AVERAGE_WAIT TOTAL_WAITS_FG TOTAL_TIMEOUTS_FG TIME_WAITED_FG AVERAGE_WAIT_FG
  ------------------------- ----------- -------------- ----------- ------------ -------------- ----------------- -------------- ---------------
  latch: row cache objects        14106              0      208739         14.8          13975              0            113296            8.11
  row cache lock                3440163              0    11800085         3.43        3440163              0          11800085            3.43

select chain_signature, osid, pid, sid, blocker_is_valid bvalid, blocker_sid, 
       p1, p1_text, p2, p3, in_wait_secs, num_waiters
  from v$wait_chains w
 order by in_wait_secs desc nulls first;
 
  CHAIN_SIGNATURE                   OSID PID SID BVALI BLOCKER_SID P1 P1_TEXT  P2 P3 IN_WAIT_SECS NUM_WAITERS
  --------------------------------- ---- --- --- ----- ----------- -- -------- -- -- ------------ -----------
  <not in a wait><='row cache lock' 2873  20 367 FALSE                                                      1
  <not in a wait><='row cache lock' 2876  22 549 TRUE          367 10 cache id  0  3            0           0

select * from v$lock where sid in (367, 549);

  ADDR      KADDR     SID TY ID1 ID2 LMODE REQUEST CTIME BLOCK 
  --------- --------- --- -- --- --- ----- ------- ----- ----- 
  18C2A1A30 18C2A1AA8 549 AE 100   0     4       0  5141     0 
  18C2A1818 18C2A1890 367 AE 100   0     4       0  5164     0 
  18C236F68 18C236FE0 549 DT   0   0     4       0     0     0 
  18C29CF40 18C29CFB8 367 DT   0   0     4       0     0     0 
Above v$wait_chains.P1 = 10 ("cache id") is dc_users. Mode requested P3 = 3 is share mode.

Last query on v$lock shows DT lock is acquired (we will have more look later).

Note that if SID1 and SID2 are opened with a user other than test_user, run the same test, P3 = 5.

If let SID2 execute alter statement on another user, for example, test_user_2:

'alter user test_user_2 identified by 123'
the session wait events are:
  buffer busy waits
  latch: cache buffers chains
As we know, Row Cache or Data Dictionary Cache in SGA shared pool holds data as rows instead of buffers. Each row cache enqueue lock is a lock on one individual row (see later discussions on v$rowcache_parent).

select * from v$sgastat where name = 'row cache';

  POOL        NAME        BYTES
  ----------- --------- -------
  shared pool row cache 8640160
After the test, kill both SID1 and SID2.


3. Blocking Test


Open two new Sqlplus sessions: SID1 (sid:371, spid:2883), and SID2 (sid:559, spid:2886).

Open one UNIX window, start a Dtrace script on SID1:

$> sudo dtrace -w -n 'pid$target:oracle:kqrpre1:return{@CNT[ustack(15, 0)] = count(); stop(); exit(0);}' -p 2883
In SID1, change user identification:

SID1 (371) >  alter user test_user identified by 123;
Immediately SID1 is suspended, and Dtrace output shows:

  dtrace: description 'pid$target:oracle:kqrpre1:return' matched 1 probe
            oracle`kqrpre1+0x6ee
            a.out`kkdlGetBaseUser+0xd7
            a.out`kzulgt1+0x91
            a.out`kksLockUserSchema+0x4f
            a.out`kksLoadChild+0x527
            a.out`kglobld+0x422
            a.out`kglobpn+0x4d0
            a.out`kglpim+0x1e9
            a.out`kglpin+0x6f9
            oracle`kxsGetRuntimeLock+0x404
            oracle`kksfbc+0x146c
            a.out`kkspsc0+0x9d7
            oracle`kksParseCursor+0x74
            oracle`opiosq0+0x70a
            a.out`kpooprx+0x102
              1
Run the same alter statement in SID2:

SID2 (559) > alter user test_user identified by 123;
SID2 is blocked by SID1 with wait event: 'row cache lock', but p3=5 (exclusive mode).

select chain_signature, osid, pid, sid, blocker_is_valid bvalid, blocker_sid, 
       p1, p1_text, p2, p3, in_wait_secs, num_waiters
  from v$wait_chains w
 order by in_wait_secs desc nulls first;
 
  CHAIN_SIGNATURE                   OSID PID SID BVALI BLOCKER_SID P1 P1_TEXT  P2 P3 IN_WAIT_SECS NUM_WAITERS
  --------------------------------- ---- --- --- ----- ----------- -- -------- -- -- ------------ ------------
  <not in a wait><='row cache lock' 2883  24 371 FALSE                                                      1
  <not in a wait><='row cache lock' 2886  26 559 TRUE          371 10 cache id  0  5          111           0
Here the Call Stack of SID2:

$> pstack 2886
   ffff80ffbbf93d4b semsys   (4, 27, ffff80ffbfff2d48, 1, ffff80ffbfff2d50)
   000000000578acd8 sskgpwwait () + f8
   000000000578a965 skgpwwait () + c5
   0000000005944ffc ksliwat () + 8dc
   0000000005944350 kslwaitctx () + 90
   0000000005bec5b8 kqrget () + 498
   0000000005b99696 kqrLockAndPinPo () + 256
   0000000005b95644 kqrpre1 () + 8d4
   000000000b787bc3 kzdugt () + 1b3
   000000000b77839d kzuial () + 6dd
   0000000005709a35 opiexe () + 4cf5
   0000000005bcdb5e opiosq0 () + 1e2e
   0000000005d202d2 kpooprx () + 102
   0000000005c72b38 kpoal8 () + 308
Resume all above executions by:

$> prun 2883
We can also make a further test on "latch: row cache objects". At first, executing the query in Blog: Oracle ROWCACHE Views and Contents - Section: 2.5. dc_users, we can find the latch address of dc_users: TEST_USER.

select user_or_role_name, indx, hash, address, cache#, cache_name, existent, lock_mode, lock_request from (
  select to_number(substr(key, 3, 2)||substr(key, 1, 2), 'XXXX') key_len,
         dump_hex2str(rtrim(substr(key, 5, 2*to_number(substr(key, 3, 2)||substr(key, 1, 2), 'XXXX')), '0')) user_or_role_name, 
         v.* 
  from v$rowcache_parent v 
  where cache_name in ('dc_users') 
  order by key)
where user_or_role_name in ('TEST_USER');

  USER_OR_ROLE_NAME  INDX  HASH ADDRESS          CACHE# CACHE_NAME E  LOCK_MODE LOCK_REQUEST
  ----------------- ----- ----- ---------------- ------ ---------- - ---------- ------------
  TEST_USER         16173 11383 000000014D5AAC08     10 dc_users   Y          0            0
  TEST_USER         12629 53120 000000014D5AAC08     10 dc_users   Y          0            0
Start Dtrace below on SID1:

$> sudo dtrace -w -n '
pid$target:oracle:kqrLockAndPinPo:entry /arg1 == 0x14D5AAC08/
{printf("\n%s:%s (arg0=>0x%X, arg1=>0x%X, arg2=>0x%X, arg3=>0x%X, arg4=>0x%X, arg5=>0x%X, arg6=>0x%X, arg7=>0x%X, arg8=>0x%X)", 
        probefunc, probename, arg0, arg1, arg2, arg3, arg4, arg5, arg6, arg7, arg8);
@CNT[ustack(15, 0)] = count(); stop(); exit(0);
}' -p 2883
In SID1, change user identification:

SID1 (371) >  alter user test_user identified by 123;

SID1 is suspended, and Dtrace shows kqrpre (row cache parent read) calling kqrLockAndPinPo:

  dtrace: description '
  pid$target:oracle:kqrLockAndPinPo:entry ' matched 1 probe
    kqrLockAndPinPo:entry (arg0=>0x7, arg1=>0x14D5AAC08, arg2=>0x17A0F8520, arg3=>0x3, arg4=>0x0, 
                           arg5=>0x0, arg6=>0x0, arg7=>0x5B9555E, arg8=>0x16FFF1D40)
       oracle`kqrLockAndPinPo
       oracle`kqrpre1+0x8d4
       oracle`kqrpre+0x24
       a.out`kkdlGetBaseUser+0xd7
       a.out`kzulgt1+0x91
       a.out`kksLockUserSchema+0x4f
       a.out`kksLoadChild+0x527
       a.out`kglobld+0x422
       a.out`kglobpn+0x4d0
       a.out`kglpim+0x1e9
       a.out`kglpin+0x6f9
       oracle`kxsGetRuntimeLock+0x404
       oracle`kksfbc+0x146c
       a.out`kkspsc0+0x9d7
       oracle`kksParseCursor+0x74
         1
In SID2, change user identification:

SID2 (559) > alter user test_user identified by 123;
SID2 is blocked by SID1 with wait event: 'latch: row cache objects'.

select chain_signature, osid, pid, sid, blocker_is_valid bvalid, blocker_sid, 
       p1, p1_text, p2, p3, in_wait_secs, num_waiters
  from v$wait_chains w
 order by in_wait_secs desc nulls first;

  CHAIN_SIGNATURE                              OSID  PID SID BVALI BLOCKER_SID         P1 P1_TEXT     P2 P3 IN_WAIT_SECS NUM_WAITERS
  -------------------------------------------- ----- --- --- ----- ----------- ---------- ---------- --- -- ------------ -----------
  <not in a wait><='latch: row cache objects'   2883  24 371 FALSE                                                                 4
  <not in a wait><='latch: row cache objects'  15590  34 723 TRUE          371 6490635480 address    411  0          163           0
  <not in a wait><='latch: row cache objects'  16187  31 187 TRUE          371 6490635480 address    411  0          126           0
  <not in a wait><='latch: row cache objects'  16189  32 375 TRUE          371 6490635480 address    411  0          125           0
  <not in a wait><='latch: row cache objects'   2886  26 559 TRUE          371 6490635480 address    411  0           18           0
  
  5 rows selected.   

  Legend:
     SID PROGRAM
     --- ----------------------------------------
     371 sqlplus.exe     <== SID1
     723 oracle@testdb (CJQ0)                 
     187 oracle@testdb (W003) KTSJ KTSJ Slave
     375 oracle@testdb (W001) KTSJ KTSJ Slave
     559 sqlplus.exe     <== SID2
Above v$wait_chains output also shows that there are other sessions also blocked by SID1 on 'latch: row cache objects'.

Here the Call Stack of SID2.

$ > pstack 2886
   ffff80ffbbf93d4b semsys   (2, 27, ffff80ffbfff2fe8, 1, 1b)
   000000000578adc5 sskgpwwait () + 1e5
   000000000578a965 skgpwwait () + c5
   000000000577cb19 kslges () + 5b9
   0000000005b9549e kqrpre1 () + 72e
   0000000005b32014 kqrpre () + 24
   000000000b265c97 kkdlGetBaseUser () + d7
   000000000b75bf31 kzulgt1 () + 91
   000000000c7ca61f kksLockUserSchema () + 4f
   0000000005d23e17 kksLoadChild () + 527
   0000000005dee052 kglobld () + 422
   0000000005ded180 kglobpn () + 4d0
   0000000005dec229 kglpim () + 1e9
   0000000005df9c59 kglpin () + 6f9
   0000000005b45804 kxsGetRuntimeLock () + 404
   0000000005b3bbac kksfbc () + 146c
   0000000005d20dd7 kkspsc0 () + 9d7
   0000000005bd04b4 kksParseCursor () + 74
   0000000005bcc43a opiosq0 () + 70a
   0000000005d202d2 kpooprx () + 102
   0000000005c72b38 kpoal8 () + 308


4. "row cache lock" Internals


In this section, we try to trace alter statement with event 10046, 10704 and Dtrace. Then look their output.

First set events: 10046 and 10704 in SID1:

SID1 > 
  alter session set events='10046 trace name context forever, level 1 : 10704 trace name context forever, level 3' 
                    tracefile_identifier='10704_rcl_7';
Then in UNIX Window, start Dtrace on SID1:

$> sudo dtrace -w -n '
pid$target:oracle:ksqgtlctx:entry,
pid$target:oracle:ksqrcl:entry, 
pid$target:oracle:kqrLockAndPinPo:entry
{printf("\n%s:%s (arg0=>0x%X, arg1=>0x%X, arg2=>0x%X)", probefunc, probename, arg0, arg1, arg2);
}' -p 2883
Run alter statement:
     
SID1 > alter user test_user identified by 123;
Terminate tracing events:

SID1 > alter session set events='10046 trace name context off : 10704 trace name context off '; 
Here the output of tracing events 10046 and 10704 (unrelated text are removed). It shows all SQL statemens, and 3 enqueue locks: DT, TM, TX.

PARSING IN CURSOR #18446604434603456984 sqlid='4dq0n3hjpcshj'
  alter user test_user iden

ksqgtl *** DT-00000000-00000000-00000000-00000000 mode=4 flags=0x10400 timeout=21474836 ***
ksucti: init txn DID from session DID 0001-001A-00006AC6

PARSING IN CURSOR #18446604434601674064 sqlid='g2rtajauwtbb6'
  select 1 from dual where exists (select 1 from sys.sysauth$ sa where privilege#=:1 and not exists 
    (select 1 from sys.user$ u where sa.grantee# = u.user# and u.type# = 1)) 
           or exists (select 1 from sys.codeauth$ where privilege#=:1)

PARSING IN CURSOR #18446604434601637344 sqlid='2z0udr4rc402m'
  select exptime, ltime, astatus, lcount from user$ where user#=:1

PARSING IN CURSOR #18446604434601672424 sqlid='0y6nfkk5dwd60'
  select pwd_verifier, pv_type from default_pwd$ where user_name = :1

PARSING IN CURSOR #18446604434601670784 sqlid='6mcm7j3g90vub'
  update user$ set user#=:1,password=:3,datats#=:4,tempts#=:5,type#=:6,defrole=:7,resource$=:8,
    ptime=DECODE(to_char(:9, 'YYYY-MM-DD'), '0000-00-00', to_date(NULL), :9),defschclass=:10, 
    spare1=:11, spare4=:12 where name=:2

ksqgtl *** TM-0018475C-00000000-00000000-00000000 mode=3 flags=0x400 timeout=21474836 ***
ksqgtl *** TX-00040006-007717CE-00000000-00000000 mode=6 flags=0x401 timeout=0 ***

EXEC #18446604434601670784

PARSING IN CURSOR #18446604434601669144 sqlid='b84cknyvnyq25'
  update user$ set exptime=DECODE(to_char(:2, 'YYYY-MM-DD'), '0000-00-00', to_date(NULL), :2),
    ltime=DECODE(to_char(:3, 'YYYY-MM-DD'), '0000-00-00', to_date(NULL), :3),
    astatus = :4, lcount = :5 where user#=:1

EXEC #18446604434601669144

ksqrcl: TX-00040006-007717CE-00000000-00000000
ksqrcl: TM-0018475C-00000000-00000000-00000000
ksqrcl: DT-00000000-00000000-00000000-00000000
We can see that DT lock is first acquired immediately after alter statement. DT is for Default Temporary Tablespace enqueue request, described as Serializes changing the default temporary tablespace and user creation.

For a normal table update, no DT lock is required.

TM and TX locks are acquired before last update statement.

The "TM-0018475C" lock is on sys.user$ table:

select owner, object_name, object_id, object_type 
from dba_objects where object_id = to_number('18475C', 'XXXXXX');

  OWNER OBJECT_NAM OBJECT_ID OBJECT_TYPE
  ----- ---------- --------- -----------
  SYS   USER$        1591132 TABLE
The involved tables are: sys.user$, sys.sysauth$, sys.codeauth$, and default_pwd$. which are all above user identifications.

Here Dtrace output (some similar lines are removed), where arg0 is v$rowcache_parent.cache#, arg1 is v$rowcache_parent.address, arg3 seems mode requested for kqrLockAndPinPo.

  kqrLockAndPinPo:entry (arg0=>0x7, arg1=>0x14D5AAC08, arg2=>0x18EE596C8)
  kqrLockAndPinPo:entry (arg0=>0x7, arg1=>0x14D5AAC08, arg2=>0x18EE596C8)
  kqrLockAndPinPo:entry (arg0=>0xA, arg1=>0x1688AEB50, arg2=>0x18EE596C8)
  kqrLockAndPinPo:entry (arg0=>0xA, arg1=>0x1688AEB50, arg2=>0x18EE596C8)
  kqrLockAndPinPo:entry (arg0=>0xA, arg1=>0x1688AEB50, arg2=>0x18EE596C8)
  kqrLockAndPinPo:entry (arg0=>0x7, arg1=>0x14D5AAC08, arg2=>0x18EE596C8)
  kqrLockAndPinPo:entry (arg0=>0x7, arg1=>0x166398748, arg2=>0x18EE596C8)
  kqrLockAndPinPo:entry (arg0=>0xA, arg1=>0x14D5AAC08, arg2=>0x184EB81B8)
  ksqgtlctx:entry       (arg0=>0x18C29CFB8, arg1=>0x4, arg2=>0x0)
  kqrLockAndPinPo:entry (arg0=>0x7, arg1=>0x166398748, arg2=>0x18EE596C8)
  kqrLockAndPinPo:entry (arg0=>0x23, arg1=>0x17BE91DB0, arg2=>0x18EE596C8)
  kqrLockAndPinPo:entry (arg0=>0xE, arg1=>0x1789631B0, arg2=>0x18EE596C8)
  kqrLockAndPinPo:entry (arg0=>0x3A, arg1=>0x178984728, arg2=>0x18EE596C8)
  ksqgtlctx:entry       (arg0=>0x184CE0220, arg1=>0x3, arg2=>0x0)
  ksqgtlctx:entry       (arg0=>0x184EB8238, arg1=>0x6, arg2=>0x0)
  ksqrcl:entry          (arg0=>0x184EB8238, arg1=>0x1, arg2=>0xFFFF80FFBFFF48A0)
  ksqrcl:entry          (arg0=>0x184CE0220, arg1=>0x1, arg2=>0x0)

Legend
  arg0 in kqrLockAndPinPo:
     select distinct to_char(cache#, 'XX') cache#_hex, cache#, cache_name
     from v$rowcache_parent where cache# in (7, 10, 35, 14, 58) order by cache#;
     
       CACHE#_HEX CACHE# CACHE_NAME
       ---------- ------ --------------------------
         7             7 dc_users
         A            10 dc_users
         E            14 dc_profiles
        23            35 triton security name to ID
        3A            58 dc_pdbdba
  
  arg0 in ksqgtlctx and ksqrcl is v$lock.kaddr, for example, 0x18C29CFB8 is DT's KADDR in above v$lock.
First there are a few kqrLockAndPinPo calls for "latch: row cache objects" requests, then enqueue get: ksqgtlctx and release: ksqrcl on "row cache lock".

Following query shows the involved dc_users:

select user_or_role_name, indx, hash, address, cache#, cache_name, existent, lock_mode, lock_request from (
  select to_number(substr(key, 3, 2)||substr(key, 1, 2), 'XXXX') key_len,
         dump_hex2str(rtrim(substr(key, 5, 2*to_number(substr(key, 3, 2)||substr(key, 1, 2), 'XXXX')), '0')) user_or_role_name, 
         v.* 
  from v$rowcache_parent v 
  where cache_name in ('dc_users') 
  order by key)
where address in ('00000001688AEB50', '000000014D5AAC08', '0000000166398748');

  USER_OR_ROLE_NAME  INDX  HASH ADDRESS          CACHE# CACHE_NAME E LOCK_MODE LOCK_REQUEST
  ----------------- ----- ----- ---------------- ------ ---------- - --------- ------------
  OUTLN             16187 21366 00000001688AEB50     10 dc_users   Y         0            0
  OUTLN             12616 41803 00000001688AEB50     10 dc_users   Y         0            0
  PUBLIC            16189 25134 0000000166398748      7 dc_users   Y         0            0
  PUBLIC            12595 19631 0000000166398748      7 dc_users   Y         0            0
  TEST_USER         16173 11383 000000014D5AAC08     10 dc_users   Y         0            0
  TEST_USER         12629 53120 000000014D5AAC08     10 dc_users   Y         0            0
We can also extend the query to find involved sessions and (recursive) transactions:

select user_or_role_name, r.indx, hash, address, cache#, cache_name, existent, lock_mode, lock_request, txn, r.saddr, s.*, t.* from (
  select to_number(substr(key, 3, 2)||substr(key, 1, 2), 'XXXX') key_len,
         k.dump_hex2str(rtrim(substr(key, 5, 2*to_number(substr(key, 3, 2)||substr(key, 1, 2), 'XXXX')), '0')) user_or_role_name, 
         v.* 
  from v$rowcache_parent v
  where cache_name in ('dc_users') 
  order by key) r, gv$session s, x$ktcxb t
where r.saddr = s.saddr(+) and r.txn = t.ktcxbxba(+)
  and txn not in ('00');
  
  -- gv$transaction is defined on x$ktcxb with filter: bitand (ksspaflg, 1) != 0 and bitand (ktcxbflg, 2) != 0

Saturday, May 2, 2020

ORA-600 [504] LATCH HIERARCHY ERROR Deadlock

Latches in Oracle are positioned in different levels (15 levels from 0 to 16 in Oracle 12c and 19c) in order to enforce ordering rules. If not complied, "LATCH HIERARCHY ERROR ORA-600 [504]" is raised and connection is aborted.

The error is well documented in MOS Docu:
    ORA-600 [504] "Trying to obtain a latch which is already held" (Doc ID 28104.1)
    
      This ORA-600 triggers when a latch request violates the ordering 
      rules for obtaining latches and granting the latch would potentially 
      result in a deadlock.
    
      These ordering rules are enforced by assigning each latch a "level#", 
      and checking requested-level vs owned-levels on each latch request. 
     
    ARGUMENTS:
      Arg [a] the requested latch address
      Arg [b] bit array of latches owned
      Arg [c] the level of the requested latch
      Arg [d] the name of the requested latch
      Arg [e] the child latch number of the requested latch
      Arg [f] if non zero, allows 2 wait gets of children
      Arg [g] address of latch owned at this level
For example,
    ORA-00600: internal error code, arguments: [504], 
               [0x18C5C8AD8], [32], [4], [enqueue hash chains], [6], [0x000000000], [], [], [], [], []
The above docu describes the latch ordering level is designed to prevent latch deadlocks when multiple latches are requested (the similar mechanism can be found in UNIX kernel code). Once a process acquires a latch of level x, it can only acquire another latch of level higher than x (monotonically increasing).

The docu also indicates that one session can simultaneously hold two or more latches as long as no ordering rule violation ("ordering" or sorting only applies if there are two or more elements).

For example, Blog Blog Oracle Redo Strand described two redo latches:
Generate Redo Entry in PGA 
    -> Server process request Redo Copy latch (which is multiple, 2*CPU_COUNT default) 
         -> Server process request redo allocation latch 
              -> allocate log buffer 
         -> release redo allocation latch 
         -> Copy Redo Entrys into Log Buffer 
  -> release Redo Copy latch
"redo allocation" is requested inside "redo copy" since the former is LEVEL# 5, the latter is LEVEL# 4,
Whereas IMU (In-memory undo buffers) is a prerequisite for using a private strand, and it has LEVEL# 0.
Therefore, the request ordering is specified by their LEVEL# as follows:

select name, level# from  v$latch where name in ('redo copy', 'redo allocation', 'In memory undo latch') order by level#; 

  NAME                  LEVEL#
  --------------------  ------
  In memory undo latch	    0
  redo copy                 4
  redo allocation           5

select name, level#, count(*) from v$latch_children where name in ('redo copy', 'redo allocation', 'In memory undo latch') 
group by name, level# order by level#; 

  NAME                 LEVEL#  COUNT(*)
  -------------------- ------  --------
  In memory undo latch      0       118
  redo copy                 4        12
  redo allocation           5       120
"Arg [f]" reveals the design consideration to "enqueue" the second willing-to-wait mode Get (in addition to the current one).

In this Blog, we will create a use case to demonstrate the error and the unexpectedly impact on real application operations.

Note: Tested in Oracle 12c, 19c


1. Test Setup


First, we create a global application context, and allocate a user lock (insert one row into sys.dbms_lock_allocated) so that two latches:
    'global ctx hash table latch' (Level 5) 
    'enqueue hash chains' (Level 4) 
will be requested in the test.

create or replace context my_ctx using my_pkg accessed globally;
/

create or replace package my_pkg is
 procedure set_ctx(p_name varchar2, p_value varchar2);
end;
/

create or replace package body my_pkg is
 procedure set_ctx(p_name varchar2, p_value varchar2) is
 begin
   dbms_session.set_context('my_ctx', p_name, p_value);
 end set_ctx;
end;
/

declare
  o_lock_hdl   varchar2(128);
begin
  dbms_lock.allocate_unique(lockname => 'MY_ULOCK', lockhandle => o_lock_hdl);
end;
/ 

---- Smoking Tests ----
exec my_pkg.set_ctx('my_lockname', 'MY_ULOCK');

select sys_context('my_ctx', 'my_lockname') var1 from dual;

select * from sys.dbms_lock_allocated where name = 'MY_ULOCK';

select addr, latch#, level#, gets, misses, sleeps, spin_gets, wait_time 
from v$latch where name = 'global ctx hash table latch';


2. Blocking Test


Open 3 Sqlplus sessions: SID1 (SPID 19944), SID2(SPID 19946), SID3. First two are test sessions, third one is a monitor session (Test in Oracle 12c on Solaris).

In SID3, run code below to display 'global ctx hash table latch':

alter system flush shared_pool;
alter system flush buffer_cache;

select addr, latch#, level#, gets, misses, sleeps, spin_gets, wait_time 
  from v$latch where name = 'global ctx hash table latch';

  ADDR     LATCH# LEVEL# GETS MISSES SLEEPS  SPIN_GETS  WAIT_TIME
  -------- ------ ------ ---- ------ ------ ---------- ----------
  60046158    429      5 6431      8      6          2 1815729481

select * from v$latch_misses 
 where parent_name = 'global ctx hash table latch' 
   and (sleep_count > 0 or wtr_slp_count > 0);

  PARENT_NAME                 WHERE                       NWFAIL_COUNT SLEEP_COUNT WTR_SLP_COUNT LONGHOLD_COUNT LOCATION                   
  --------------------------- --------------------------- ------------ ----------- ------------- -------------- ---------------------------
  global ctx hash table latch kzctxgscv: allocate context            0           6             0              5 kzctxgscv: allocate context
  global ctx hash table latch kzctxggcv: get context val             0           0             6              0 kzctxggcv: get context val   
For SID1 (SPID 19944), we also open an UNIX terminal, and run Dtrace:

sudo dtrace -w -n  \
'
pid$target::kslfre:entry /arg0 == 0x60046158/  {
  printf("\n%s:%s (Addr=>0x%X, Mode=>%d, PID=>0x%X)", probefunc, probename, arg0, arg4, arg5);
  @CNT[ustack(10, 0)] = count();
  stop(); exit(0);
  }
' -p 19944 
Then set context by:

SID1 (SPID 19944) > exec my_pkg.set_ctx('my_lockname', 'MY_ULOCK');
Immediately we can see SID1 was suspended, and Dtrace output displays latch request parameter and call stack. It shows that latch is requested in "Mode=>16" (probably exclusive mode).

  dtrace: description '
  pid$target::kslfre:entry ' matched 1 probe
  dtrace: allowing destructive actions
   CPU     ID                    FUNCTION:NAME
     4  81237                     kslfre:entry
  kslfre:entry (Addr=>0x60046158, Mode=>16, PID=>0x2000000000000018)
  
      oracle`kslfre
      oracle`kzctxgset+0x195
      oracle`kzctxgscv+0x5e7
      oracle`kzctxesc+0x789
      oracle`pevm_icd_call_common+0x29d
      oracle`pfrinstr_ICAL+0x90
      oracle`pfrrun_no_tool+0x12a
      oracle`pfrrun+0x4c0
      oracle`plsql_run+0x288
      oracle`peicnt+0x946
Run the same queries in SID3 again to show latch usage statistics (latch GETS increasing 1) and latch holder:

select addr, latch#, level#, gets, misses, sleeps, spin_gets, wait_time 
from v$latch where name = 'global ctx hash table latch';

  ADDR     LATCH# LEVEL# GETS MISSES SLEEPS  SPIN_GETS  WAIT_TIME
  -------- ------ ------ ---- ------ ------ ---------- ----------
  60046158    429      5 6432      8      6          2 1815729481

select * from v$latchholder;

  PID  SID LADDR    NAME                        GETS 
  --- ---- -------- --------------------------- ---- 
   24   10 60046158 global ctx hash table latch 6432 
Now in SID2, we run a Plsql block below to access global context to return lock_name, and then get user lock with it.

SID2 (SPID 19946) > 
  declare 
   l_lockname   varchar2(1000);
   l_lockid     number;
  begin
   l_lockname := sys_context('my_ctx', 'my_lockname'); 
   select lockid into l_lockid from sys.dbms_lock_allocated where name = l_lockname;
  end;
  / 
It is blocked by SID1 on 'global ctx hash table latch' request. Probably since SID1 held it in exclusive mode ("Mode=>16"). We can run queries in SID3 to display the blocking chain.

select * from v$latch_misses 
 where parent_name = 'global ctx hash table latch' 
   and (sleep_count > 0 or wtr_slp_count > 0);
   
  PARENT_NAME                 WHERE                       NWFAIL_COUNT SLEEP_COUNT WTR_SLP_COUNT LONGHOLD_COUNT LOCATION                   
  --------------------------- --------------------------- ------------ ----------- ------------- -------------- ---------------------------
  global ctx hash table latch kzctxgscv: allocate context            0           7             0              5 kzctxgscv: allocate context
  global ctx hash table latch kzctxggcv: get context val             0           0             7              0 kzctxggcv: get context val 

select (select s.program from v$session s where sid=w.sid) program
      ,chain_signature, osid, pid, sid
      ,blocker_is_valid bvalid, blocker_sid, p1, p1_text, p2, p3, in_wait_secs, num_waiters
  from v$wait_chains w
 order by in_wait_secs desc nulls first;
 
  PROGRAM CHAIN_SIGNATURE OSID  PID SID BVALI BLOCKER_SID         P1 P1_TEXT   P2 P3 IN_WAIT_SECS NUM_WAITERS
  ------- --------------- ----- --- --- ----- ----------- ---------- -------- --- -- ------------ -----------
  sqlplus <='latch free'  19944  24  10 FALSE                                                               1
  sqlplus <='latch free'  19946  23 903 TRUE           10 1610899800 address  429  0           46           0
Now we kill SID1 process by:

kill -9 19944 
Immediately SID2 throws ORA-00600 error:

SID2 (SPID 19946) > declare
    2  l_lockname   varchar2(1000);
    3  l_lockid     number;
    4  begin
    5  l_val := sys_context('my_ctx', 'my_lockname');
    6  select lockid into l_lockid from sys.dbms_lock_allocated where name = l_lockname;
    7  end;
    8  /
  declare
  *
  ERROR at line 1:
  ORA-00600: internal error code, arguments: [504], 
    [0x18C5C8AD8], [32], [4], [enqueue hash chains], [6], [0x000000000], [], [], [], [], []
Look the generated incident file, call stack shows that the error was raised in subroutine: "ksl_level_check" ("ERROR SIGNALED: yes"). It signifies that once we already held Level 5: 'global ctx hash table latch', but still require level 4 'enqueue hash chains' latch, hence ordering rule is violated (5 < 4).

  ========= Dump for incident 274833 (ORA 600 [504]) ========
  [TOC00003]
  ----- Beginning of Customized Incident Dump(s) -----
  *** LATCH HIERARCHY ERROR ***
  An attempt to get the 'enqueue hash chains' latch (child #6) at level 4 (address = 0x18c5c8ad8)
  from location 'ksq.h LINE:2656 ID:ksqgtl3' (also see call stack below)
  conflicts with the following held latch(es):
   Level 5: 'global ctx hash table latch' (address = 0x60046158)
    gotten from location 'kzctxg.h LINE:595 ID:kzctxggcv: get context val'
  
  --------------------- Binary Stack Dump ---------------------
  [1]  (ksedst()+307 -> skdstdst()) 
  [2]  (dbkedDefDump()+1121 -> ksedst()) 
  [3]  (ksedmp()+304 -> dbkedDefDump()) 
  [4]  (dbgexPhaseII()+2387 -> ksedmp()) 
  [5]  (dbgexExplicitEndInc()+1325 -> dbgexPhaseII()) 
  [6]  (dbgeEndDDEInvocationImpl()+875 -> dbgexExplicitEndInc()) 
  [7]  (ksl_level_check()+2673 -> dbgeEndDDEInvocation()) 
          CALL TYPE: call   ERROR SIGNALED: yes   COMPONENT: VOS
  [8]  (kslgetl()+409 -> ksl_level_check()) 
  [9]  (ksqgtlctx()+1324 -> kslgetl()) 
  [10] (ksqgelctx()+615 -> ksqgtlctx()) 
  [11] (kksfbc()+5913 -> ksqgelctx()) 
  [12] (kkspbd0()+801 -> kksfbc()) 
  [13] (kksParseCursor()+452 -> kkspbd0()) 
  [14] (opiosq0()+1802 -> kksParseCursor()) 
  [15] (opipls()+2568 -> opiosq0()) 
In SID3, run query again, latch GETS, MISSES and SLEEPS all increased 1.

select addr, latch#, level#, gets, misses, sleeps, spin_gets, wait_time 
from v$latch where name = 'global ctx hash table latch';

  ADDR     LATCH# LEVEL# GETS MISSES SLEEPS SPIN_GETS  WAIT_TIME
  -------- ------ ------ ---- ------ ------ --------- ----------
  60046158    429      5 6433      9      7         2 1961502719
The incident file shows that we are trying to get 'enqueue hash chains' latch (child #5) at level 4 (address = 0x18c5c8ad8). Subroutine "kksParseCursor" and "kksfbc" (Kernel Kompile Shared Find Bound Cursor) in call stack indicate that that this request comes from SQL parsing. To make a lookup of shared resource stored in an array of hash buckets, searching text has to hash to an array index, acquiring latch, and then traverse hash chain to access the shared resource.

With following query, we can also list this child latch.

select name, addr, latch#, child#, level#, gets, misses, sleeps, spin_gets
from v$latch_children where addr like '%18C5C8AD8';

  NAME                ADDR      LATCH# CHILD# LEVEL#     GETS MISSES SLEEPS  SPIN_GETS
  ------------------- --------- ------ ------ ------ -------- ------ ------ ----------
  enqueue hash chains 18C5C8AD8     36      6      4 74790437     81      0         81
Note that 'global ctx hash table latch' is a single latch (without children), but 'enqueue hash chains' has a few children (6 in test DB).

In above test, we manually kill SID1 process. In real applications, this can happen when session is abnormally terminated (for example, when memory is under pressure, OS can choose one process to kill).

Above test also shows that when SID1 is killed, the unaware SID2 is abruptly disconnected, an unexpectedly impact on real application operations.


3. Non-Blocking Test


Instead of setting global context value in above test, we will look what happens if we only get global context value.

In SID3, run code below:

alter system flush shared_pool;
alter system flush buffer_cache;

select addr, latch#, level#, gets, misses, sleeps, spin_gets, wait_time 
from v$latch where name = 'global ctx hash table latch';

  ADDR     LATCH# LEVEL# GETS MISSES SLEEPS  SPIN_GETS  WAIT_TIME
  -------- ------ ------ ---- ------ ------ ---------- ----------
  60046158    429      5 6721     10      7          3 1961502719
Again run the same Dtrace for SID1 (SPID 20024):

sudo dtrace -w -n  \
'
pid$target::kslfre:entry /arg0 == 0x60046158/  {
  printf("\n%s:%s (Addr=>0x%X, Mode=>%d, PID=>0x%X)", probefunc, probename, arg0, arg4, arg5);
  @CNT[ustack(10, 0)] = count();
  stop(); exit(0);
  }
' -p 20024
In SID1, get global context value:

SID1 (SPID 20024) > 
  declare 
   l_val        varchar2(1000);
  begin
   l_val := sys_context('my_ctx', 'var1'); 
  end;
  / 
Dtrace shows calling from getter: kzctxGblCtxGet (in above Blocking Test, that is setter: kzctxgset):

  dtrace: description '
  pid$target::kslfre:entry ' matched 1 probe
  dtrace: allowing destructive actions
   CPU     ID                    FUNCTION:NAME
     2  81237                     kslfre:entry
  kslfre:entry (Addr=>0x60046158, Mode=>1, PID=>0x4B)
  
      oracle`kslfre
      oracle`kzctxGblCtxGet+0x841
      oracle`kzctxAppCtxValGet3+0x481
      oracle`psdsysctx+0x1eb
      oracle`pessysctx2+0xe3
      oracle`pevm_icd_call_common+0x12b
      oracle`pfrinstr_BCAL+0x4e
      oracle`pfrrun_no_tool+0x12a
      oracle`pfrrun+0x4c0
      oracle`plsql_run+0x288
Query of latch statistics in SID3 shows GETS increasing 1, and single latch 'global ctx hash table latch' is held by SID1.

select addr, latch#, level#, gets, misses, sleeps, spin_gets, wait_time 
from v$latch where name = 'global ctx hash table latch';

  ADDR     LATCH# LEVEL# GETS MISSES SLEEPS  SPIN_GETS  WAIT_TIME
  -------- ------ ------ ---- ------ ------ ---------- ----------
  60046158    429      5 6722     10      7          3 1961502719

select * from v$latchholder;

   PID SID LADDR    NAME                        GETS
  ---- --- -------- --------------------------- ---- 
    24  10 60046158 global ctx hash table latch 6722 
Repeat above same SID2 (SPID 20026) code:

SID2 (SPID 20026) > 
  declare 
   l_lockname   varchar2(1000);
   l_lockid     number;
  begin
   l_lockname := sys_context('my_ctx', 'my_lockname'); 
   select lockid into l_lockid from sys.dbms_lock_allocated where name = l_lockname;
  end;
  / 

  PL/SQL procedure successfully completed.
SID2 is not blocked by SID1. Above Dtrace output shows that SID1 latch request is "Mode=>1" (probably shared mode).

Query of latch statistics in SID3 shows GETS incrasing 1, but not MISSES and SLEEPS even though single latch 'global ctx hash table latch' is still held by SID1.

select addr, latch#, level#, gets, misses, sleeps, spin_gets, wait_time 
from v$latch where name = 'global ctx hash table latch';

  ADDR     LATCH# LEVEL# GETS MISSES SLEEPS  SPIN_GETS  WAIT_TIME
  -------- ------ ------ ---- ------ ------ ---------- ----------
  60046158    429      5 6723     10      7          3 1961502719


4. Direct Subroutine Call Test


Blog: Oracle 12 and latches, part 3 (Frits Hoogland Weblog) shows that latch get subrountine: "ksl_get_shared_latch" can be directly called. We will try it with following test (in Oracle 19c on Linux).

In SID3, run query below to get 'global ctx hash table latch' address and stats:

select addr, latch#, level#, gets, misses, sleeps, spin_gets, wait_time 
from v$latch where name = 'global ctx hash table latch';

  ADDR     LATCH# LEVEL#  GETS MISSES SLEEPS  SPIN_GETS  WAIT_TIME
  -------- ------ ------ ----- ------ ------ ---------- ----------
  60077140    589      5 10879     10      2          8         57
In SID1, call "ksl_get_shared_latch" to acquire 'global ctx hash table latch':

SID1 > oradebug setmypid
  Statement processed.
  
SID1 > oradebug call ksl_get_shared_latch 0x60077140 1 0 4618 16
  Function returned 1
In SID2, set global context: (Note that in previous two tests, we set global context in SID1)

SID2 > exec my_pkg.set_ctx('my_lockname', 'MY_ULOCK');
SID2 is blocked by SID1 with Wait Event: 'latch free'.

Now back to SID1, and run query (to request 'enqueue hash chains' latch). Immediately SID1 throws the same ORA-00600 [504].

SID1 > select lockid from sys.dbms_lock_allocated where name = 'MY_ULOCK';
  select lockid from sys.dbms_lock_allocated where name = 'MY_ULOCK'
  *
  ERROR at line 1:
  ORA-00600: internal error code, arguments: [504], [0x0B41C6288], [32], [4],
  [enqueue hash chains], [6], [0x000000000], [], [], [], [], []
  
and incident file contains the detail:

  ORA-00600: internal error code, arguments: [504], 
    [0x0B41C6288], [32], [4], [enqueue hash chains], [6], [0x000000000], [], [], [], [], []
  
  ========= Dump for incident 45273 (ORA 600 [504]) ========
  [TOC00003]
  ----- Beginning of Customized Incident Dump(s) -----
  *** LATCH HIERARCHY ERROR ***
  An attempt to get the 'enqueue hash chains' latch (child #6) at level 4 (address = 0xb41c6288)
  from location 'ksq.h LINE:2721 ID:ksqgtl3' (also see call stack below)
  conflicts with the following held latch(es):
   Level 5: 'global ctx hash table latch' (address = 0x60077140)
    gotten from location 'krvx.h LINE:18027 ID:krvxpaf: activate'
  
  --------------------- Binary Stack Dump ---------------------
  [1]  (ksedst1()+95 -> kgdsdst())
  [2]  (ksedst()+58 -> ksedst1())
  [3]  (dbkedDefDump()+23080 -> ksedst())
  [4]  (ksedmp()+577 -> dbkedDefDump())
  [5]  (dbgexPhaseII()+2092 -> ksedmp())
  [6]  (dbgexExplicitEndInc()+285 -> dbgexPhaseII())
  [7]  (dbgeEndDDEInvocationImpl()+314 -> dbgexExplicitEndInc())
  [8]  (ksl_level_check()+2746 -> dbgeEndDDEInvocationImpl())
          CALL TYPE: call   ERROR SIGNALED: yes   COMPONENT: VOS
  [9]  (kslgetl()+2800 -> ksl_level_check())
  [10] (ksqgtlctx()+1873 -> kslgetl())
  [11] (ksqgelctx()+838 -> ksqgtlctx())
  [12] (kksfbc()+17684 -> ksqgelctx())
  [13] (kkspsc0()+1566 -> kksfbc())
  [14] (kksParseCursor()+114 -> kkspsc0())
  [15] (opiosq0()+2310 -> kksParseCursor())
In SID1, we first held Level 5: 'global ctx hash table latch', and subsequently requests Level 4: 'enqueue hash chains' latch (child #6) in order to parse (kksParseCursor) our submitted SQL, the latch ordering rule is violated, hence ORA-00600: [504] LATCH HIERARCHY ERROR.

If we look again SID2, it runs through.

SID2 > exec my_pkg.set_ctx('my_lockname', 'MY_ULOCK');
  PL/SQL procedure successfully completed.

Tuesday, April 7, 2020

Index Service ITL and Recursive Transaction

Continuing with previous Blog:
     Cache Buffer Chains Latch Contention Case Study-1: Reverse Key Index
     Index Block Split Point Distribution,
this Blog will first demonstrates Index Service ITL usage and Recursive Transaction during index block splits, and then, as an example, gives a proof of their existence in index stats gathering.

We will trace transaction with Enqueue Trace Event 10704, and make index block / undo header block dumps to observe Index Service ITL and Recursive Transaction.


1. Test


First repeat our previous setup by inserting 4707 rows:

truncate table test_tab;
insert into test_tab select level, -level from dual connect by level <= 4707;
commit;
Then collect meta info:

select object_name, object_id, to_char(object_id, 'XXXXXXXX') id_hex, data_object_id, to_char(data_object_id, 'XXXXXXXX') did_hex 
from dba_objects where object_name in ('TEST_TAB', 'TEST_TAB#R');

  OBJECT_NAME  OBJECT_ID  ID_HEX  DATA_OBJECT_ID  DID_HEX
  -----------  ---------  ------  --------------  -------
  TEST_TAB     2459814    2588A6  2462199         2591F7
  TEST_TAB#R   2461548    258F6C  2462198         2591F6

-- index block for id: 1 to 11
select blk, count(*), min(id) min_id, max(id) max_id from (
  select id 
        ,dbms_rowid.rowid_block_number(sys_op_lbid (2461548, 'L', rowid)) blk
    from test_tab)  
where id between 1 and 11
group by blk order by 1, min_id, blk;

  BLK      COUNT(*)  MIN_ID  MAX_ID
  -------  --------  ------  ------
  3704663  11        1       11

-- find index root block for later dump
select segment_name, header_file, header_block, (header_block+1) root_block from dba_segments where segment_name = 'TEST_TAB#R';
  SEGMENT_NAME  HEADER_FILE  HEADER_BLOCK  ROOT_BLOCK
  ------------  -----------  ------------  ----------
  TEST_TAB#R    1548         3704658       3704659  
Trace row 4708 insert with Event 10704. First setup Trace Events:

alter session set events='10046 trace name context forever, level 1 : 10704 trace name context forever, level 3' 
                  tracefile_identifier='10704_r1_insert';
Then, open an UNIX window, start a Dtrace script to suspend process when Oracle gets to "ksqrcl:return" (session SPID: 543),

$ > sudo dtrace -w -n 'pid$target:oracle:ksqrcl:return {@CNT[ustack(5, 0)] = count(); stop(); exit(0);}' -p 543
Now make row 4708 insert:
           
insert into test_tab values(4708, -4708);
Immediately, process stopped, and Dtrace displays:
  
  oracle`ksqrcl+0xa
  oracle`ktucmt+0xe95
  oracle`ktcCommitTxn_new+0x35d
  oracle`ktccrb2+0x85
  oracle`kdisle+0x4a219
    1
From other Sqlplus session, run a query on gv$transaction:

select RECURSIVE, addr, xidusn, xidslot, xidsqn, status, ses_addr, start_scn, xid, prv_xid,
       flag, DECODE (BITAND (flag, 32), 0, 'NO', 'YES') flag_recur
  from gv$transaction v;

  RECURSIVE ADDR      XIDUSN XIDSLOT XIDSQN   STATUS   SES_ADDR  START_SCN     XID              PRV_XID           FLAG     FLAG_RECUR
  --------- --------- ------ ------- -------- -------- --------- ------------- ---------------- ----------------  -------- ----------
  NO        1866294E8 2      33      14402489 ACTIVE   18EE42590 9447170829632 02002100B9C3DB00 0000000000000000  3587      NO
  YES       18662A088 1      30      7334024  INACTIVE 18EE42590 9447170829684 01001E0088E86F00 02002100B9C3DB00  67116587  YES   
We can see two transactions for the same Oracle session (SES_ADDR: 18EE42590). One is marked RECURSIVE: NO; another is YES. Their ADDR and XID are different. Recursive transaction has its PRV_XID (02002100B9C3DB00) same as XID of main transaction. Recursive transaction is started after main transaction, which is showed by START_SCN: 9447170829632 < 9447170829684.

Index leaf block split also performed.

select blk, count(*), min(id) min_id, max(id) max_id from (
  select id 
        ,dbms_rowid.rowid_block_number(sys_op_lbid (2461548, 'L', rowid)) blk
    from test_tab)  
where id between 1 and 11
group by blk order by 1, min_id, blk;

  BLK      COUNT(*)  MIN_ID  MAX_ID
  -------  --------  ------  ------
  3704663  5         1       5
  3665613  6         6       11
Dump index root block (one block after header_block of segment TEST_TAB#R):

-- dump index root block 3704659 
alter session set tracefile_identifier = "index_root_block_3704659_insert";
alter system dump datafile 1548 block 3704659;

   Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
  0x01   0x0001.01e.006fe888  0x00c07b03.5855.03  --U-    1  fsc 0x0000.9742ed75  
Xid shows that it is done by RECURSIVE transaction, already committed (Flag: "--U-" for fast commit), Scn/Fsc filled with "0x0000.9742ed75".

So RECURSIVE transaction on root block is committed even that main transaction on leaf block is still open. Probably it is controlled by some Oracle internal mechanism, and more interestingly, this commit is independent to the commit of main transaction, so that contentions (locking duration) on root and branch blocks are minimized.

Note that there is only one Itl entry for index root and branch block, named Service Itl.

Open 10704 Trace file, all lines about TX are as follows:

  ksqgtl *** TX-00020021-00DBC3B9-00000000-00000000 mode=6 flags=0x401 timeout=0 ***
  ksqgtl: xcb=0x1866294e8, ktcdix=2147483647, topxcb=0x1866294e8
  
  ksqgtl *** TX-0001001E-006FE888-00000000-00000000 mode=6 flags=0x401 timeout=0 ***
  ksqgtl: xcb=0x18662a088, ktcdix=2147483647, topxcb=0x1866294e8
It shows two Transactions: TX-00020021 (Undo Segment 2, Slot 0x021=33) and TX-0001001E (Undo Segment 1, Slot 0x01E=30). TX-0001001E has TX-00020021 as topxcb=0x1866294e8 (TX-0001001E is a recursive transaction of TX-00020021, performed in the same session).

Now resume UNIX process (prun 543), 10704 Trace file is added with lines below. Recursive transaction: TX-0001001E returns with ksqrcl (release lock) although recursive transaction already committed before.

  ksqrcl: TX-0001001E-006FE888-00000000-00000000
  ksqrcl: returns 0
Terminate 10704 Trace:

alter session set events='10046 trace name context off : 10704 trace name context off ';  
Query v$transaction, only main transaction for row 4708 insert is open, recursive transaction committed:

-- XIDSQN: 14402489 = 0xdbc3b9
select xidusn, xidslot,xidsqn, ubafil, ubablk, ubasqn, ubarec, status from v$transaction;

  XIDUSN  XIDSLOT  XIDSQN    UBAFIL  UBABLK  UBASQN  UBAREC  STATUS
  ------ --------  --------  ------  ------  ------  ------  ------
  2       33       14402489  3       17248   18029   15      ACTIVE
Then make index block dump for the new split block, and look its two Itl (leaf block has at least two Itl, the first one is reserved as Service Itl):

alter system checkpoint;
alter system flush buffer_cache;

-- dump new index block 3665613 (contains row 6 and new row 4708)
alter session set tracefile_identifier = "index_block_3665613_insert";
alter system dump datafile 1548 block 3665613;

   Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
  0x01   0x0001.01e.006fe888  0x00c07b03.5855.01  CB--    0  scn 0x0897.9742ed75
  0x02   0x0002.021.00dbc3b9  0x00c04360.b993.0f  ----    1  fsc 0x0000.00000000
First Itl is committed, second Itl is still open (Flag: '----', Lck: 1, Scn/Fsc not filled). We can see first Itl is marked with Xid (0x0001.01e.006fe888), same as Itl of above index root block. So root block and leaf block split are performed by the same recursive transaction, but leaf block Uba (0x00c07b03.5855.01) is before root Uba (0x00c07b03.5855.03) (same "block address" and "block sequence number", but different "record within block", 01 vs. 03).

Find Undo Segment headers (segment_id 0x0001 and 0x0002) for both Itl:

-- Itl 0x01 is Service Itl 
select segment_name, file_id, segment_id, block_id from dba_rollback_segs where segment_id in (1, 2); 

  SEGMENT_NAME          FILE_ID  SEGMENT_ID  BLOCK_ID
  --------------------  -------  ----------  --------
  _SYSSMU1_1118279661$  3        1           776
  _SYSSMU2_3069567101$  3        2           872
Dump both Itl Undo Segment Headers:

-- dump Service Itl undo header 776 (Xid: 0x0001.01e.006fe888, undo segment 1, slot 0x01e)
alter session set tracefile_identifier = "undo_header_776_insert";
alter system dump datafile 3 block 776;

  index  state cflags  wrap#    uel         scn         dba        stmt_num    cmt
  ------ ----- ------ --------- ------- --------------- ---------- ----------- ---------- 
   0x1e    9    0x00  0x6fe888  0x0021  0x0897.9742ed75 0x00c07b03 0x00000000  1583849538   
   
-- dump current active (state 10) TRX  XID undo header 872 (Xid: 0x0002.021.00dbc3b9, undo segment 2, slot 0x021)
alter session set tracefile_identifier = "undo_header_872_insert";
alter system dump datafile 3 block 872;

  index  state cflags  wrap#    uel         scn         dba        stmt_num    cmt
  ------ ----- ------ --------- ------- --------------- ---------- ----------- ---
   0x21   10    0x80  0xdbc3b9  0x000b  0x0897.9742ed40 0x00c04360 0x00000000  0
First Itl is committed (state 9) and stamped with cmt (commit time): 1583849538. Second Itl is active (state 10).

Now trace commit with Event 10704:

alter session set events='10046 trace name context forever, level 1 : 10704 trace name context forever, level 3' 
                  tracefile_identifier='10704_r1_commit';
commit;
alter session set events='10046 trace name context off : 10704 trace name context off ';

  XCTEND rlbk=0, rd_only=0, tim=7414747162919
  ksqrcl: TX-00020021-00DBC3B9-00000000-00000000
  ksqrcl: returns 0
The main transaction TX-00020021 terminated (XCTEND) and released lock (ksqrcl).

Dump again index block of new split block:

alter system checkpoint;
alter system flush buffer_cache;

-- dump new index block 3665613 (contains row 6 and new row 4708)
alter session set tracefile_identifier = "index_block_3665613_commit";
alter system dump datafile 1548 block 3665613;

   Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
  0x01   0x0001.01e.006fe888  0x00c07b03.5855.01  CB--    0  scn 0x0897.9742ed75
  0x02   0x0002.021.00dbc3b9  0x00c04360.b993.0f  C---    0  scn 0x0897.9742efa1
Both Itl are committed. Scn/Fsc in second Itl (9742efa1) is bigger than that of first Itl (9742ed75).

Dump again both Undo Segment Headers:

-- dump Service Itl undo header 776 (Xid: 0x0001.01e.006fe888, undo segment 1, slot 0x01e)
alter session set tracefile_identifier = "undo_header_776_commit";
alter system dump datafile 3 block 776;

  index  state cflags  wrap#    uel         scn         dba        stmt_num    cmt
  ------ ----- ------ --------- ------- --------------- ---------- ----------- ---------- 
   0x1e    9    0x00  0x6fe888  0x0021  0x0897.9742ed75 0x00c07b03 0x00000000  1583849538 
   
-- dump just committed TRX XID undo header 872 (Xid: 0x0002.021.00dbc3b9, undo segment 2, slot 0x021)
alter session set tracefile_identifier = "undo_header_872_commit";
alter system dump datafile 3 block 872;

  index  state cflags  wrap#    uel         scn         dba        stmt_num    cmt
  ------ ----- ------ --------- ------- --------------- ---------- ----------- ----------
   0x21    9    0x00  0xdbc3b9  0x000b  0x0897.9742efa1 0x00c04360 0x00000000  1583850562  
Second Itl is also committed (state 9) and stamped with cmt: 1583850562, which is bigger than that of first Itl: 1583849538. So recursive transaction is committed before main transaction, and started after main transaction, or its lifecycle is totally inside main transaction.


2. Service ITL and Recursive Transaction with Index Stats


Now we can have a look of the impact caused by Recursive Transaction.

Open two Sqlplus sessions: SID1 and SID2.

In SID1, we create table and index with one row insert:

SID1 > 
  drop table test_service_itl purge;
  
  create table test_service_itl
    as select level x, rpad('Test Service ITL', 100, 'X') y from dual connect by level <= 1; 
    
  create index test_service_itl#i#1 on test_service_itl(x, y);
In SID2, insert 1,000,000 rows without commit:

SID2 > 
  insert into test_service_itl
    select level x, rpad('Test Service ITL', 100, 'X') y from dual connect by level <= 1e6; 
Back to In SID1, gather stats, run queries, and make index root block dump and index treedump.:

SID1 >
  exec dbms_stats.gather_table_stats(null, 'TEST_SERVICE_ITL', cascade=> true);

  select blevel, leaf_blocks, num_rows from dba_indexes v where index_name = 'TEST_SERVICE_ITL#I#1';
  
    BLEVEL  LEAF_BLOCKS  NUM_ROWS
    ------  -----------  --------
         2            1         1
  
  -- find index root block for later dump
  select segment_name, header_file, header_block, (header_block+1) root_block 
    from dba_segments where segment_name = 'TEST_SERVICE_ITL#I#1';
    
    SEGMENT_NAME                   HEADER_FILE HEADER_BLOCK ROOT_BLOCK
    ------------------------------ ----------- ------------ ----------
    TEST_SERVICE_ITL#I#1                  1678      2257586    2257587
  
  -- dump index root block 2257587 
  alter session set tracefile_identifier = "index_root_block_2257587";
  alter system dump datafile 1678 block 2257587;
  
     Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
    0x01   0x006c.00d.00003b62  0x00c1be06.0e31.04  C---    0  scn  0x000008ceef036f76
    Branch block dump
    =================
    header address 4233650252=0xfc58604c
    kdxcolev 2
    KDXCOLEV Flags = - - -
    kdxcolok 0
    kdxcoopc 0x80: opcode=0: iot flags=--- is converted=Y
    kdxconco 3
    kdxcosdc 2
    kdxconro 21
    kdxcofbo 70=0x46
    kdxcofeo 7846=0x1ea6
    kdxcoavs 7776
    kdxbrlmc 1795863=0x1b6717
    kdxbrsno 20
    kdxbrbksz 8056 
    kdxbr2urrc 0
    
  select object_name, object_id, to_char(object_id, 'XXXXXXXX') id_hex, 
                      data_object_id, to_char(data_object_id, 'XXXXXXXX') did_hex 
  from dba_objects where object_name = 'TEST_SERVICE_ITL#I#1';
  
             OBJECT_NAME  OBJECT_ID  ID_HEX  DATA_OBJECT_ID  DID_HEX
    --------------------  ---------  ------  --------------  -------
    TEST_SERVICE_ITL#I#1 3305086  326E7E         3305086   326E7E
  
  -- dump index treedump  
  alter session set tracefile_identifier = "index_treedump_3305086";
  alter session set events 'immediate trace name treedump level 3305086';

    ----- begin tree dump
    branch: 0x2272b3 2257587 (0: nrow: 22, level: 2)
       branch: 0x1b6717 1795863 (-1: nrow: 682, level: 1)
          leaf: 0x2272b5 2257589 (-1: row:69.69 avs:61)
          leaf: 0x2272b6 2257590 (0: row:69.69 avs:24)
          leaf: 0x2272b7 2257591 (1: row:68.68 avs:109)
          leaf: 0x18032d 1573677 (2: row:68.68 avs:108)
          leaf: 0x18032e 1573678 (3: row:68.68 avs:109)
The index stats shows that both NUM_ROWS and LEAF_BLOCKS are 1 since un-committed 1,000,000 rows are not gathered. However BLEVEL is 2 because BLEVEL is updated by Recursive Transaction with Index Service ITL, which has already committed as showed by the index root Itl:

     Itl           Xid                  Uba         Flag  Lck        Scn/Fsc
    0x01   0x006c.00d.00003b62  0x00c1be06.0e31.04  C---    0  scn  0x000008ceef036f76
Therefore index meta data BLEVEL is computed independent of user data NUM_ROWS and LEAF_BLOCKS. BLEVEL is updated by recursive transaction, others are updated by main transaction.

The above test is an indirect proof of Service ITL and Recursive Transaction existence.

Index Block Split Point Distribution

Continuing with previous Blog: Cache Buffer Chains Latch Contention Case Study-1: Reverse Key Index, this Blog will look the split point distribution of index block, specially for Reverse Key Index.


1. Index Split Stats


In this case study, I have also learned from others to look index split stats in v$sesstat or v$sysstat.

For example, insert 1'000'000 rows, and look leaf/branch/root node splits.

truncate table test_tab;

select sid, n.name, s.value 
  from v$mystat s, v$statname n 
 where s.statistic# = n.statistic#
   and name in ('root node splits', 'branch node splits', 'leaf node splits');
   
insert into test_tab select level, -level from dual connect by level <= 1e6;
commit;

select sid, n.name, s.value 
  from v$mystat s, v$statname n 
 where s.statistic# = n.statistic#
   and name in ('root node splits', 'branch node splits', 'leaf node splits');   
Here the output:
   
  SID  NAME                VALUE
  368  leaf node splits    0
  368  branch node splits  0
  368  root node splits    0

SQL (368,56362) > insert into test_tab select level, -level from dual connect by level <= 1e6;
  1'000'000 rows inserted.
   
  SID  NAME                VALUE
  368  leaf node splits    2964
  368  branch node splits  4
  368  root node splits    1


2. Split Point Distribution


The appended Plsql: indx_splits_stats_get can be used to get the exact point of index split. For example, insert 10'000 rows, and look split point distribution:

exec indx_splits_stats_get(1e4, 1);

select t.*, ins_row -lag(ins_row) over(order by ins_row) rows_between
from  indx_splits_stats t
where run=1 
order by ins_row;   

  RUN  INS_ROW  SID  ROOT_SPLITS  BRANCH_SPLITS  LEAF_SPLITS  ROWS_BETWEEN
  ---  -------  ---  -----------  -------------  -----------  ------------
  1    541      902  0            0              1
  1    996      902  0            0              2            455
  1    1131     902  0            0              3            135
  1    1967     902  0            0              4            836
  1    1994     902  0            0              5            27
  1    2310     902  0            0              6            316
  1    2325     902  0            0              7            15
  1    3959     902  0            0              8            1634
  1    3986     902  0            0              9            27
  1    4047     902  0            0              10           61
  1    4074     902  0            0              11           27
  1    4442     902  0            0              12           368
  1    4625     902  0            0              13           183
  1    4708     902  0            0              14           83
  1    4719     902  0            0              15           11
  1    7563     902  0            0              16           2844
  1    7671     902  0            0              17           108
  1    7689     902  0            0              18           18
  1    7758     902  0            0              19           69
  1    7797     902  0            0              20           39
  1    7884     902  0            0              21           87
  1    8251     902  0            0              22           367
  1    8278     902  0            0              23           27
  1    8837     902  0            0              24           559
  1    8942     902  0            0              25           105
  1    9128     902  0            0              26           186
  1    9209     902  0            0              27           81
  1    9220     902  0            0              28           11
  1    9827     902  0            0              29           607
  
  29 rows selected.
There are 29 'leaf node splits', in average, 344 rows per split. However, column ROWS_BETWEEN shows that the minimum distance between two splits are 11 rows, the maximum is 2844, about 258 (2844/11) times of difference, an irregular and unpredictable split distribution.

If we rebuild index test_tab#r as noreverse, inserting 10'000 rows will have only 18 'leaf node splits', every split occurs exactly after 533 rows insert, an totally even distribution.


3. Test Code: indx_splits_stats_get



drop view sesstat_v;

create view sesstat_v as
select sid, n.name, s.value from v$sesstat s, v$statname n where s.statistic# = n.statistic#;

drop table indx_splits_stats;

create table indx_splits_stats as
select 0 run, 0 ins_row, sid
       ,sum(decode(name, 'root node splits', value, 0))   as root_splits
       ,sum(decode(name, 'branch node splits', value, 0)) as branch_splits
       ,sum(decode(name, 'leaf node splits', value, 0))   as leaf_splits
  from sesstat_v where sid = -1 group by sid;

create or replace procedure indx_splits_stats_get(p_ins_rows number, p_run number) as
  l_sid             number := sys.dbms_support.mysid;
  l_root_splits_pre     number := 0;
  l_branch_splits_pre   number := 0;
  l_leaf_splits_pre     number := 0;
  l_root_splits     number := 0;
  l_branch_splits   number := 0;
  l_leaf_splits     number := 0;  
begin
  execute immediate 'truncate table test_tab';

  select sum(decode(name, 'root node splits', value, 0))   as root_splits
        ,sum(decode(name, 'branch node splits', value, 0)) as branch_splits
        ,sum(decode(name, 'leaf node splits', value, 0))   as leaf_splits
        into l_root_splits_pre, l_branch_splits_pre, l_leaf_splits_pre
  from sesstat_v where sid = l_sid;
  
  for i in 1..p_ins_rows loop
    insert into test_tab values(i, -i);
    commit;
    select sum(decode(name, 'root node splits', value, 0))   as root_splits
          ,sum(decode(name, 'branch node splits', value, 0)) as branch_splits
          ,sum(decode(name, 'leaf node splits', value, 0))   as leaf_splits
          into l_root_splits, l_branch_splits, l_leaf_splits
    from sesstat_v where sid = l_sid;
   
   if l_root_splits != l_root_splits_pre or l_branch_splits != l_branch_splits_pre or l_leaf_splits != l_leaf_splits_pre 
   then
     dbms_output.put_line('--- Leaf Splitted at row count: '||i||
                          ', '||l_root_splits||','||l_branch_splits||','||l_leaf_splits||',');
     insert into indx_splits_stats values(p_run, i, l_sid, l_root_splits, l_branch_splits, l_leaf_splits);
     l_root_splits_pre   := l_root_splits;
     l_branch_splits_pre := l_branch_splits;
     l_leaf_splits_pre   := l_leaf_splits; 
     commit;
  end if; 
  end loop; 
end;
/

-- exec indx_splits_stats_get(1e4, 1);