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);  

Cache Buffer Chains Latch Contention Case Study-3: index root block Modification Blocking

Continuing from previous Blog: Cache Buffer Chains Latch Contention Case Study-2: Reverse Primary Key Index, we will look index root (branch) block CBC latch blocking, and its impacts to entire system.

At first we will find one row in an unrelated noise table, which is hashed to the same CBC latch as index root block.

In the first session, we update that unrelated row, and stop it by suspending CBC latch request.

In the second session, insert one row into our test table to trigger a leaf block split, which results in root block modification (insert of new split leaf block). Since they share the same CBC latch, the second session is also blocked.

Consequently any other session (e.q. SMON, DB Writer) which requires that CBC latch is also blocked.

Note: Tested in Oracle 12c, 19c

1. Test Setup

Same as previous blog, we create a table with one unique key reverse index (usually recommended to reduce index contention):

drop table test_tab purge;

create table test_tab (id number, val number);

create unique index test_tab#r on test_tab(id) reverse;

alter table test_tab add constraint test_tab#r primary key (id);

and again find the same leaf block split point:

SQL > exec leaf_split_finder(5000);

  --- Leaf Splitted at row count: 4906, (id between 1 and 11) in 2 Blocks
  block: 2661263, cnt: 5, min_id: 1, max_id: 5
  block: 3665621, cnt: 6, min_id: 6, max_id: 11

Then create a noise table with one idnex: (see right linked book: Oracle Database Performance Tuning (Studies . Practices . Researches) - Chapter 3: Locks, Latches and Mutexes)

drop table cbc_noise purge;

create table cbc_noise 
  as select level x, rpad('CBC_NOISE', 100, 'X') y, level seq from dual connect by level < 1e6; 

--- insert more rows by:
-- insert into cbc_noise select * from cbc_noise;

commit;
  
create index cbc_noise#i#1 on cbc_noise(x, y);

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

Collect all meta info:

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      2661258    2661259

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         2464078  25994E
TEST_TAB#R   2464076 25994C         2464077  25994D

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 ('CBC_NOISE', 'CBC_NOISE#I#1');

OBJECT_NAME   OBJECT_ID ID_HEX  DATA_OBJECT_ID DID_HEX
------------- --------- ------  -------------- -------
CBC_NOISE       2464039 259927         2464067  259943
CBC_NOISE#I#1   2464043 25992B         2464066  259942  

2. Prepare Test

With above index root block number (2661259), we can find noise table index blocks which share the same CBC latch.

select * from (
with sq as (select object_name, data_object_id 
              from dba_objects 
             where object_name in ('TEST_TAB#R', 'CBC_NOISE#I#1')
            )
    ,bh as (select hladdr, obj, file#, dbablk, sum(tch) tch 
              from sys.x_bh group by hladdr, obj, file#, dbablk)
select hladdr cbc_latch_addr
      ,sum(tch) tch
      ,listagg(tch || '-' || obj || '(' || object_name || ')/' || file# || '/' ||dbablk, ';') 
         within group (order by tch desc) tch_list -- "tch-obj(name)/file/blk_list"
      ,count(*) blk_cnt
from  bh, sq
where bh.obj = sq.data_object_id
  and tch > 0
--  and (hladdr like '%18B6072A8%')   
group by hladdr
order by tch desc)
where 1=1
  and (tch_list like '%TEST_TAB#R%2661259%')
;

CBC_LATCH_ADDR   TCH TCH_LIST                                BLK_CNT
---------------- --- --------------------------------------  -------
000000018B6072A8  7  3-2464048(TEST_TAB#R)   /1548/2661259    3
                     2-2464066(CBC_NOISE#I#1)/1548/1482751
                     2-2464066(CBC_NOISE#I#1)/1548/1511408

The above output shows that latch 0x18B6072A8 protects TEST_TAB#R root block (2661259), and two CBC_NOISE#I#1 blocks (1482751, 1511408).

Take one CBC_NOISE#I#1 block, for example, 1482751, we can list all its indexed table rows.

select blk, x from (
  select x 
        ,dbms_rowid.rowid_block_number(sys_op_lbid (2464043, 'L', rowid)) blk
    from cbc_noise)  
where blk in (1482751);

       BLK          X
---------- ----------
   1482751     200656
   1482751     200657
   ...
   
60 rows selected. 

Now we insert 4905 rows into test_tab, that is exactly one row before index leaf block split:

truncate table test_tab;

insert into test_tab select level, -level from dual connect by level <= 4905;

commit;

-- using above index object_id to substitute for 2458815
select blk, count(*), min(id) min_id, max(id) max_id from (
  select id 
        ,dbms_rowid.rowid_block_number(sys_op_lbid (2464076, 'L', rowid)) blk
    from test_tab)  
where id between 1 and 11
group by blk order by min_id, blk;

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

3. Blocking Test

Open 3 Sqlplus sessions.

3.1 Session-1: Update cbc_noise

At first, start appended dtrace_stop.d to trace Session-1 on above shared CBC latch (same Dtrace script as Blog: Cache Buffer Chains Latch Contention Case Study-1: Reverse Key Index ).

Then in Session-1 (SPID 8438, SID 184), update one found row of cbc_noise, for example, x = 200656:

SQL (SPID 8438, SID 184) >  update cbc_noise set y = 'cbc_test' where x = 200656;

Session-1 is suspended, and here the Dtrace output:

oracle@testdb > ksh ./dtrace_stop.d 8438 0x18B6072A8

dtrace: allowing destructive actions
 CPU     ID                    FUNCTION:NAME
   2  81245       ksl_get_shared_latch:entry
---------Step 1 at 2020 Apr 5 06:33:03 (Elapsed-ns=1580535694)---------
***State Entry>>>(nproc_pid=>0, flag=>0, gets=>86515, latch=>228, level=>1, where=>2195)
>>>Transition>>>ksl_get_shared_latch:entry
      (Addr=>0x18B6072A8, Immed_Get=>1, Why=>0, Where=>2141(0x85D), Mode=>16, PID=>0x200000000000001A)
              oracle`ksl_get_shared_latch
              a.out`kcbget+0x3411
              a.out`ktbxchg+0x10c
              a.out`kdifind+0x504
              a.out`kdimod0+0x2360
              a.out`kauXuFinish+0x1a8
              a.out`kxibFinish+0x2bc
              oracle`qerupFetch+0x993
              a.out`qerstFetch+0x543
              oracle`updaul+0x92c
              oracle`updThreePhaseExe+158
              oracle`updexe+307
              oracle`opiexe+2c55
              oracle`kpoal8+a45

   2  81246      ksl_get_shared_latch:return
>>>State Return***(nproc_pid=>26, flag=>536870912, gets=>86516, latch=>228, level=>1, where=>2141)
   5      2                             :END
---------Step 2 at 2020 Apr 5 06:33:03 (Elapsed-ns=420179764)---------
Latch Gets = 0 (86515 - 86515)


(where=>2195: kcbgtcr: fast path pin
 where=>2141: kcbget: new pin)

By the way, above Call Stack shows call of subroutine "updThreePhaseExe", which is related to Oracle Write Consistency ("updaul" is "update Attempt Update of all rows or Lock all rows"). For full Call Stack, see Appendix: Session-1 (SID 184).

3.2 Session-2: Insert to Trigger Leaf Block Split and Root Block Modification

At first, start appended dtrace_kslgess.d to trace Session-2 on shared latch (same Dtrace script as Blog: Cache Buffer Chains Latch Contention Case Study-2: Reverse Primary Key Index).

Then in Session-2 (SPID 8668, SID 367), insert one row into test_tab. Immediately it is blocked by Session-1 in Wait Event: 'latch: cache buffers chains'.

SQL (SPID 8668, SID 367) >> insert into test_tab values(4906, -4906);

Here the Dtrace output:

oracle@testdb > ksh ./dtrace_kslgess.d 8668 0x18B6072A8

dtrace: allowing destructive actions
 CPU     ID                    FUNCTION:NAME
   0  81263                    kslgess:entry
---------Step 1 at 2020 Apr 5 06:33:43 (Elapsed-ns=19370786619)---------
***State Entry>>>(nproc_pid=>26, flag=>536870912, gets=>86516, latch=>228, level=>1, where=>2141)
>>>Transition>>>kslgess:entry
      (Addr=>0x18B6072A8, Where=>2196)
              oracle`kslgess
              oracle`kcbgcur+0xd45
              oracle`ktbgcur+0xb4
              a.out`kdifind+0x39a
              a.out`kdiins1+0xa3c
              a.out`kdiinsp0+0x7b
              a.out`kauxsin+0x799
              a.out`qesltcLoadIndexList+0x36e
              a.out`qerltcSimpleSingleInsRowCBK+0x5a
              a.out`qerltcSingleRowLoad+0x150

3.3 Session-3: Select Statement

In Session-3, we start one select on test_tab, and it is also blocked by Session-1 in Wait Event: 'latch: cache buffers chains'.

SQL (SPID 8670, SID 548) > select * from test_tab where id = 234;

Therefore any statements which require that root block access hit the contention at the same latch. But other sessions, which do not touch this CBC latch (directly or indirectly), are still running. In this case, we can observe some session working, some blocked.

4. System-Wide Blocking

Let system run with the above blocking for a while. One hour later, run a query on v$wait_chains, order them by blocking sequence (IN_WAIT_SECS). It shows SMON, DB Writer and other background processes also blocked in wait event: 'latch: cache buffers chains' or 'buffer busy waits' (file#=3 is UNDO file).

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, in_wait_secs, num_waiters
  from v$wait_chains w
 order by in_wait_secs desc nulls first;


PROGRAM CHAIN_SIGNATURE                                    OSID  PID SID BVALID BLOCKER_SID P1         P1_TEXT IN_WAIT_SECS NUM_WAITERS
------- -------------------------------------------------- ----  --- --- ------ ----------- ---------- ------- ------------ -----------
sqlplus 'latch: cache buffers chains'<='buffer busy waits' 8438  26  184 FALSE                                                       7              
sqlplus 'latch: cache buffers chains'                      8668  25  367 TRUE   367         6633321128 address       6,286           0               
sqlplus 'latch: cache buffers chains'                      8670  27  548 TRUE   367         6633321128 address       6,257           0               
(DBW0)  'latch: cache buffers chains'                      15528 11  897 TRUE   367         6633321128 address       6,106           0               
(M001)  'latch: cache buffers chains'<='buffer busy waits' 12184 32  368 TRUE   367         6633321128 address       4,675           3               
(SMON)  'latch: cache buffers chains'<='buffer busy waits' 15540 15  541 TRUE   368         3          file#         4,375           0               
(W002)  'latch: cache buffers chains'<='buffer busy waits' 12186 23  903 TRUE   368         3          file#         4,374           0               
(M000)  'latch: cache buffers chains'<='buffer busy waits' 12474 36  5   TRUE   368         3          file#           245           0                 

P1 value "6633321128 = 0x18B6072A8" is the CBC latch address.

IN_WAIT_SECS indicates the blocking sequence.

NUM_WAITERS shows number of sessions blocked by this session. In above example, 4 are directly blocked, 3 indirectly blocked (blocking chain).

Appendex-3 lists their Call Stacks.

5. Blocking Objects and Blocks

To terminate the blocking, run command "prun 8438" to terminate the blocking.

With above shared latch address 0x18B6072A8, we can run a query to list its protected objects and blocks currently in use:

select * from (
with sq as (select object_name, data_object_id 
              from dba_objects 
             -- where object_name in ('TEST_TAB#R', 'CBC_NOISE#I#1')
            )
    ,bh as (select hladdr, obj, file#, dbablk, sum(tch) tch 
              from sys.x_bh group by hladdr, obj, file#, dbablk)
select hladdr cbc_latch_addr
      ,sum(tch) tch
      ,listagg(tch || '-' || obj || '(' || object_name || ')/' || file# || '/' ||dbablk, ';') 
         within group (order by tch desc) tch_list -- "tch-obj(name)/file/blk_list"
      ,count(*) blk_cnt
from  bh, sq
where bh.obj = sq.data_object_id
  and tch > 0
  and (hladdr like '%18B6072A8%')   
group by hladdr
order by tch desc)
;

CBC_LATCH_ADDR   TCH TCH_LIST                                BLK_CNT
---------------- --- --------------------------------------  -------
000000018B6072A8  9  2-2464089(TEST_TAB#R)    /1548/2661259    5
                     4-2464066(CBC_NOISE#I#1) /1548/1482751
                     1-8      (C_FILE#_BLOCK#)/1/111481    
                     1-8      (SEG$)          /1/111481    
                     1-8      (UET$)          /1/111481    

We can see the system objects (C_FILE#_BLOCK#, SEG$, UET$) under this latch. Hence all sessions which access those object blocks hit the same CBC contention.

In summary, this Blog is trying to manually hold a CBC latch to simulate CBC latch contention. It demonstrated that one unrelated DML can block other index root (branch) operations by CBC latch, and even has system-wide impacts.

6. Index Root Block CBC Latch Contention Test

Similar to two previous Blog: Cache Buffer Chains Latch Contention Case Study-1: Reverse Key Index and Cache Buffer Chains Latch Contention Case Study-2: Reverse Primary Key Index, we start 12 Job sessions to access test_tab:

exec test_tab_select_job(6, 1e9, 1, 0);

exec test_tab_select_job(6, 1e9, 6, 0);

-- stop all jobs by:
--   exec clean_jobs;

Then open two Sqlplus sessions, one updates cbc_noise in a loop, another selects any one row from test_tab in a loop.

begin
  for i in 1..1e9 loop
    update cbc_noise set y = 'cbc_test' where x = 200656;
  end loop;
end;
/

begin
  for i in 1..1e9 loop
    for c in (select * from test_tab where id = 234) loop
      null;
    end loop;
  end loop;
end;
/

We can observe the heavy CBC latch contention on latch child: '000000018B6072A8', which protects test_tab index root block and the updated cbc_noise index block (and also other blocks). In real applications, it implies that a sporadic heavy DML on an unrelated table can affect other running sessions, and makes the performance issues hard to track / reproduce.

select s.program, s.client_identifier, s.sid, s.serial#, p.pid, p.spid, s.event, p1, p2, p3, latchwait, latchspin
  from v$session s, v$process p
 where s.paddr=p.addr and (lower(s.program) like '%j0%' or lower(s.program) like '%sql%') 
 order by s.client_identifier; 

  PROGRAM               CLIENT_IDENTIFIER     SID  SERIAL#  PID  SPID   EVENT                        P1          P2   P3
  --------------------  --------------------  ---  -------  ---  ----   ---------------------------  ----------  ---  --
  oracle@testdb (J000)  test_tab_select_id_1  369  58913    26   21665  latch: cache buffers chains  6633321128  228   0 
                        ...                                                                                            
  oracle@testdb (J006)  test_tab_select_id_6  546  11249    39   21675  latch: cache buffers chains  6633321128  228   0  
                        ...                                                                                            
  sqlplus.exe                                 727  61279    46   21740  latch: cache buffers chains  6633321128  228   0
  sqlplus.exe                                 729  40349    44   21917  latch: cache buffers chains  6633321128  228   0 


select * from v$latch_misses 
 where parent_name = 'cache buffers chains' and sleep_count > 0
 order by sleep_count desc;

  WHERE                     NWFAIL_COUNT  SLEEP_COUNT  WTR_SLP_COUNT  LONGHOLD_COUNT  LOCATION
  ------------------------  ------------  -----------  -------------  --------------  -----------------------
  kcbgtcr: fast path exam   0             5283         4592           840             kcbgtcr: fast path exam
  kcbso1: set no access     0             477          1236           18              kcbso1: set no access  
  kcbgtcr: fast path pin    0             66           34             22              kcbgtcr: fast path pin 
  kcbgcur: fast path excl   0             38           11             24              kcbgcur: fast path excl
  kcbget: new pin           0             33           0              21              kcbget: new pin        
  kcbchg: cr pin change     0             10           2              5               kcbchg: cr pin change  
  kcbchg: change complete   0             5            8              4               kcbchg: change complete

 
select * from v$latchholder;

  PID  SID  LADDR             NAME                  GETS
  ---  ---  ----------------  --------------------  ----------
  24   10   000000018B6072A8  cache buffers chains  142727994

select latch#, child#, addr, gets, misses, sleeps, spin_gets, wait_time, round(wait_time/sleeps) us_per_sleep 
  from v$latch_children 
 where addr = hextoraw('000000018B6072A8'); 

  LATCH#  CHILD#  ADDR              GETS       MISSES    SLEEPS   SPIN_GETS  WAIT_TIME    US_PER_SLEEP
  ------  ------  ----------------  ---------  --------  -------  ---------  ----------   ------------
  228     15672   000000018B6072A8  191753377  1460415   6280     1454291    27969528879  4453747

7. Appendix

7.1 dtrace_stop.d

sudo dtrace -w -n \
'
typedef unsigned int ub4;

typedef struct latchstate /* latch state */ {
    ub4 nproc_pid;  /* Nproc or pid   */
    ub4 flag;       /* blocking flag  */
    ub4 gets;       /* number of gets */
    ub4 latch;      /* latch number   */
    ub4 level;      /* latch level    */
    ub4 where; } latchstate;

BEGIN {laddr = $1; step = 1; begin_gets = 0, end_gets = 0; prev_ts = timestamp;
   self->evt = "begin"; self->loc = 0x0;}
pid$target::ksl_get_shared_latch:entry /arg0 == laddr && (self->evt != probefunc || self->loc != arg3)/ {
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   ls = ((latchstate *) copyin(arg0, sizeof(latchstate)));
   begin_gets = (begin_gets == 0 ? ls->gets: begin_gets); end_gets = ls->gets;
   printf("\n***State Entry>>>(nproc_pid=>%d, flag=>%d, gets=>%d, latch=>%d, level=>%d, where=>%d)"
           ,ls->nproc_pid, ls->flag, ls->gets, ls->latch, ls->level, ls->where);
   printf("\n>>>Transition>>>%s:%s\n      (Addr=>0x%X, Immed_Get=>%d, Why=>%d, Where=>%d(0x%X), Mode=>%d, PID=>0x%X)",
          probefunc, probename, arg0, arg1, arg2, arg3, arg3, arg4, arg5);
   self->evt = probefunc; self->loc = arg3;
   ustack(14, 0);
   /* stop(); exit(0); */    /* no latch blocking, failed get, try again */
   step = step + 1; self->entry = 1; prev_ts = timestamp;}
pid$target::ksl_get_shared_latch:return /self->entry == 1/ {
   ls = ((latchstate *) copyin(laddr, sizeof(latchstate)));
   printf("\n>>>State Return***(nproc_pid=>%d, flag=>%d, gets=>%d, latch=>%d, level=>%d, where=>%d)"
           ,ls->nproc_pid, ls->flag, ls->gets, ls->latch, ls->level, ls->where);
   stop(); exit(0);      /* simulate long latch holder, run by: dtrace -w -n */
   self->entry = 2;}
pid$target::kslfre:entry /self->entry == 2 && arg0 == laddr && self->evt != probefunc/ {
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   ls = ((latchstate *) copyin(arg0, sizeof(latchstate)));
   end_gets = ls->gets;
   printf("\n>>>Transition>>>%s:%s(Addr=>0x%-X)", probefunc, probename, arg0);
   self->evt = probefunc; self->loc = 0x0;
   /* stop(); exit(0); */      /* simulate long latch holder, run by: dtrace -w -n */
   printf("\n===Latch freed===");
   ustack(10, 0); step = step + 1; prev_ts = timestamp;}
END {
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   printf("\nLatch Gets = %d (%d - %d)", (end_gets - begin_gets), (unsigned long)begin_gets, (unsigned long)end_gets); }
' -p $1 $2

7.2 dtrace_kslgess.d

sudo dtrace -w -n \
'
typedef unsigned int ub4;

typedef struct latchstate /* latch state */ {
    ub4 nproc_pid;  /* Nproc or pid   */
    ub4 flag;       /* blocking flag  */
    ub4 gets;       /* number of gets */
    ub4 latch;      /* latch number   */
    ub4 level;      /* latch level    */
    ub4 where; } latchstate;

BEGIN {laddr = $1; step = 1; begin_gets = 0, end_gets = 0; prev_ts = timestamp;
   self->evt = "begin"; self->loc = 0x0;}
pid$target::kslgess:entry /arg0 == laddr && (self->evt != probefunc || self->loc != arg4)/ {
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   ls = ((latchstate *) copyin(arg0, sizeof(latchstate)));
   begin_gets = (begin_gets == 0 ? ls->gets: begin_gets); end_gets = ls->gets;
   printf("\n***State Entry>>>(nproc_pid=>%d, flag=>%d, gets=>%d, latch=>%d, level=>%d, where=>%d)"
           ,ls->nproc_pid, ls->flag, ls->gets, ls->latch, ls->level, ls->where);
   printf("\n>>>Transition>>>%s:%s\n      (Addr=>0x%X, Where=>%d)",
          probefunc, probename, arg0, arg4);
   self->evt = probefunc; self->loc = arg4;
   ustack(10, 0);
   /*stop(); exit(0);*/    /* no latch blocking, failed get, try again */
   step = step + 1; self->entry = 1; prev_ts = timestamp;}
pid$target::kslgess:return /self->entry == 1/ {
   ls = ((latchstate *) copyin(laddr, sizeof(latchstate)));
   printf("\n>>>State Return***(nproc_pid=>%d, flag=>%d, gets=>%d, latch=>%d, level=>%d, where=>%d)"
           ,ls->nproc_pid, ls->flag, ls->gets, ls->latch, ls->level, ls->where);
   /*stop(); exit(0);*/    /* simulate long latch holder, run by: dtrace -w -n */
   self->entry = 2;}
pid$target::kslfre:entry /self->entry == 2 && arg0 == laddr && self->evt != probefunc/ {
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   ls = ((latchstate *) copyin(arg0, sizeof(latchstate)));
   end_gets = ls->gets;
   printf("\n>>>Transition>>>%s:%s(Addr=>0x%-X)", probefunc, probename, arg0);
   self->evt = probefunc; self->loc = 0x0;
   /*stop(); exit(0);*/      /* simulate long latch holder, run by: dtrace -w -n */
   printf("\n===Latch freed===");
   ustack(10, 0); step = step + 1; prev_ts = timestamp;}
END {
   printf("\n---------Step %d at %Y (Elapsed-ns=%d)---------", step, walltimestamp, (timestamp-prev_ts));
   printf("\nLatch Gets = %d (%d - %d)", (end_gets - begin_gets), (unsigned long)begin_gets, (unsigned long)end_gets); }
' -p $1 $2

7.3 Call Stacks

7.3.1 Session-1 (SID 184) 'latch: cache buffers chains'<='buffer busy waits'

oracle@testdb > pstack 8438
 8438:   testdb (LOCAL=NO)
 ------------  lwp# 1 / thread# 1  ---------------
  00000000059e3711 kcbget () + 3411
  00000000059e01cc ktbxchg () + 10c
  00000000059de834 kdifind () + 504
  00000000059d70e0 kdimod0 () + 2360
  000000000d986c88 kauXuFinish () + 1a8
  000000000f5485ac kxibFinish () + 2bc
  0000000005729233 qerupFetch () + 993
  00000000092cc193 qerstFetch () + 543
  00000000057234ec updaul () + 92c
  0000000005720428 updThreePhaseExe () + 158
  000000000571f6d7 updexe () + 307
  0000000005707995 opiexe () + 2c55
  0000000005c73275 kpoal8 () + a45
  00000000056f87e3 opiodr () + 433
  0000000005701323 ttcpip () + 593
  00000000056fd59c opitsk () + 6cc
  00000000056fc405 opiino () + 3c5
  00000000056f87e3 opiodr () + 433
  00000000056f7dcb opidrv () + 33b
  00000000056f79fa sou2o () + 7a
  00000000056f7775 opimai_real () + 265
  00000000056f70be ssthrdmain () + 22e
  00000000056f6e64 main () + a4

7.3.2 Session-2 (SID 367) 'latch: cache buffers chains'

----- without using dtrace_kslgess.d, only use pstack

oracle@testdb > pstack 8668
 8668:   testdb (LOCAL=NO)
 ------------  lwp# 1 / thread# 1  ---------------
  ffff80ffbbf93d4b semsys   (2, 27, ffff80ffbffe21e8, 1, a45)
  000000000578adc5 sskgpwwait () + 1e5
  000000000578a965 skgpwwait () + c5
  000000000578972d kslgess () + 92d
  00000000057a9be5 kcbgcur () + d45
  00000000057eecb4 ktbgcur () + b4
  00000000059de6ca kdifind () + 39a
  0000000005a224fc kdiins1 () + a3c
  0000000005a21a5b kdiinsp0 () + 7b
  0000000005a1e269 kauxsin () + 799
  0000000005a1c42e qesltcLoadIndexList () + 36e
  0000000005ae06fa qerltcSimpleSingleInsRowCBK () + 5a
  0000000005a1b210 qerltcSingleRowLoad () + 150
  0000000005a19f36 qerltcFetch () + 1d6
  00000000092cc11a qerstFetch () + 4ca
  0000000005a19297 insexe () + 407
  00000000057064df opiexe () + 179f
  0000000005c73275 kpoal8 () + a45
  00000000056f87e3 opiodr () + 433
  0000000005701323 ttcpip () + 593
  00000000056fd59c opitsk () + 6cc
  00000000056fc405 opiino () + 3c5
  00000000056f87e3 opiodr () + 433
  00000000056f7dcb opidrv () + 33b
  00000000056f79fa sou2o () + 7a
  00000000056f7775 opimai_real () + 265
  00000000056f70be ssthrdmain () + 22e
  00000000056f6e64 main () + a4

7.3.3 oracle@testdb (DBW0 SID 897) 'latch: cache buffers chains'

oracle@testdb > pstack 15528 
 15528:  ora_dbw0_testdb
 ------------  lwp# 1 / thread# 1  ---------------
  ffff80ffbbf93d4b semsys   (2, 27, ffff80ffbfff88a8, 1, 623f7)
  000000000578adc5 sskgpwwait () + 1e5
  000000000578a965 skgpwwait () + c5
  000000000578972d kslgess () + 92d
  00000000057889bf ksl_get_shared_latch () + 39f
  00000000066154ec kcbbxsv () + 2fc
  00000000066119f9 kcbb_coalesce () + 149
  0000000008c389d5 kcbbwdl () + 655
  000000000660b716 kcbbdrv () + df6
  00000000065d9443 ksbcti () + 583
  00000000065cfadd ksbabs () + 91d
  00000000065cde36 ksbrdp () + 6c6
  000000000627c9fc opirip () + 34c
  00000000056f7d1b opidrv () + 28b
  00000000056f79fa sou2o () + 7a
  00000000056f764d opimai_real () + 13d
  00000000056f70be ssthrdmain () + 22e
  00000000056f6e64 main () + a4

7.3.4 oracle@testdb (SMON SID 541)'latch: cache buffers chains'<='buffer busy waits'

oracle@testdb > pstack 15540
 15540:  ora_smon_testdb
  ffff80ffbbf93d4b semsys   (4, 27, ffff80ffbfff70c8, 1, ffff80ffbfff70d0)
  000000000578acd8 sskgpwwait () + f8
  000000000578a965 skgpwwait () + c5
  0000000005944ffc ksliwat () + 8dc
  0000000005944350 kslwaitctx () + 90
  0000000005955d2d kcbzwb () + 86d
  00000000057aeadc kcbgcur () + 5c3c
  00000000057a551a ktuGetUsegHdr () + 3da
  00000000067ba665 kturRecoverUndoSegment () + 1f5
  00000000067b87e3 kturRecoverActiveTxns1 () + 4d3
  00000000067b8252 kturRecoverActiveTxns () + 22
  00000000067b6697 ktprbeg1 () + 177
  00000000067b645f ktprbeg () + 1f
  00000000067b16fc ktmmon () + fbc
  00000000067afe94 ktmSmonMain () + f4
  00000000065cde36 ksbrdp () + 6c6
  000000000627c9fc opirip () + 34c
  00000000056f7d1b opidrv () + 28b
  00000000056f79fa sou2o () + 7a
  00000000056f764d opimai_real () + 13d
  00000000056f70be ssthrdmain () + 22e
  00000000056f6e64 main () + a4

7.3.5 oracle@testdb (W002 SID 903) 'latch: cache buffers chains'<='buffer busy waits'

oracle@testdb > pstack 12186
 12186:  ora_w002_testdb
  ffff80ffbbf93d4b semsys   (4, 27, ffff80ffbfff5e88, 1, ffff80ffbfff5e90)
  000000000578acd8 sskgpwwait () + f8
  000000000578a965 skgpwwait () + c5
  0000000005944ffc ksliwat () + 8dc
  0000000005944350 kslwaitctx () + 90
  0000000005955d2d kcbzwb () + 86d
  00000000057aeadc kcbgcur () + 5c3c
  00000000057a551a ktuGetUsegHdr () + 3da
  0000000005ae819a ktuGetExtTxnInfo () + 2ca
  00000000062131dd ktuxcm () + 9d
  00000000057a6f9d ktecgetsh () + 67d
  00000000057a6903 ktecgshx () + 23
  0000000005c39c26 kteinicnt3 () + 2e6
  0000000005c3992c kteinicnt1 () + 2c
  0000000008dea761 ktssupd_segment_extblks_bkg () + 511
  0000000006287799 ktsj_task_switch () + 149
  0000000006286100 ktsj_execute_task () + 2b0
  0000000006284d6e ktsj_slave_main () + 42e
  000000000627ddcd ksvrdp () + aed
  000000000627c9ab opirip () + 2fb
  00000000056f7d1b opidrv () + 28b
  00000000056f79fa sou2o () + 7a
  00000000056f764d opimai_real () + 13d
  00000000056f70be ssthrdmain () + 22e
  00000000056f6e64 main () + a4

7.3.6 oracle@testdb (M001 SID 368) 'latch: cache buffers chains'<='buffer busy waits'

oracle@testdb > pstack 12184
 12184:  ora_m001_testdb
 ------------  lwp# 1 / thread# 1  ---------------
  ffff80ffbbf93d4b semsys   (2, 27, ffff80ffbffb28a8, 1, f6)
  000000000578adc5 sskgpwwait () + 1e5
  000000000578a965 skgpwwait () + c5
  000000000578972d kslgess () + 92d
  00000000057889bf ksl_get_shared_latch () + 39f
  000000000579b3bc kcbnew () + 3c9c
  00000000057957c7 ktugnb () + 327
  0000000005790ad8 ktugur () + a08
  000000000574359e ktuchg2 () + 49e
  0000000005743007 ktbchg2 () + 1d7
  0000000005a81c6b kdisle () + 3ed3b
  0000000005a25ae3 kdiins1 () + 4023
  0000000005a1e8fc kauxsin () + e2c
  0000000005a1c659 qesltcLoadIndexList () + 599
  0000000005afff45 qerltcFlushKdtBuffer () + 225
  0000000005b2e1c4 qerltcBufRow () + 74
  0000000005b2dbd2 qerltcKdtBufferedInsRowCBK () + 152
  0000000005afea47 qerltcLoadStateMachine () + 237
  0000000005fd71b1 qerltcInsertSelectRop () + 101
  00000000092cb832 qerstRowP () + 412
  00000000092cb832 qerstRowP () + 412
  0000000005d1c2f3 qerfxFetch () + c73
  00000000092cc11a qerstFetch () + 4ca
  0000000005c78d3f rwsfcd () + 6f
  00000000092cc11a qerstFetch () + 4ca
  0000000005a1a211 qerltcFetch () + 4b1
  00000000092cc11a qerstFetch () + 4ca
  0000000005a19297 insexe () + 407
  00000000057064df opiexe () + 179f
  0000000005c73275 kpoal8 () + a45
  00000000056f87e3 opiodr () + 433
  0000000005de3542 kpoodrc () + 22
  000000000571a07d rpiswu2 () + 2fd
  0000000005de3187 kpoodr () + 287
  0000000005de272b upirtrc () + e0b
  0000000005de18e0 kpurcsc () + 70
  0000000005ddc2da kpuexec () + 1b0a
  0000000005dda7bb OCIStmtExecute () + 2b
  0000000005f1914f kewrgwxf1_gwrsql_exft_1 () + 3df
  0000000005f180bb kewrgwxf_gwrsql_exft () + 23b
  0000000009aabb65 kewrft_flush_table () + 4e5
  0000000009aaaeab kewrftec_flush_table_ehdlcx () + c7b
  0000000009ab9b3a kewrfat1_flush_all_tables_1 () + 42a
  0000000009aba3ec kewrfat_flush_all_tables () + 3ec
  0000000009abb5a6 kewrfop_flush_one_phase () + 226
  0000000009abbedb kewrfap_flush_all_phases () + 7b
  0000000009aa5eb2 kewrfos_flush_onesnap () + bf2
  0000000009aa6b14 kewrfsc_flush_snapshot_c () + 564
  0000000009aa4ad0 kewrcmdbs_flush_mdb_snap () + 460
  0000000009af4283 kewrafs_auto_flush_slave () + 6e3
  000000000633455c kebm_slave_main () + 29c
  000000000627ddcd ksvrdp () + aed
  000000000627c9ab opirip () + 2fb
  00000000056f7d1b opidrv () + 28b
  00000000056f79fa sou2o () + 7a
  00000000056f764d opimai_real () + 13d
  00000000056f70be ssthrdmain () + 22e
  00000000056f6e64 main () + a4