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.