On Oracle: 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.

Tuesday, April 7, 2020

Index Service ITL and Recursive Transaction

1. Test

2. Service ITL and Recursive Transaction with Index Stats