TM lock and No Transaction Commit, TX & TM Locks and No Transaction Visible

Oracle Document wrote:

TRANSACTION 
  groups SQL statements so that they are either all committed, which means they are applied to the database, or all rolled back, 
  which means they are undone from the database. Oracle Database assigns every transaction a unique identifier called a transaction ID.

AUTONOMOUS TRANSACTION
  an independent transaction that can be called from another transaction, which is the main transaction. You can suspend the calling transaction, 
  perform SQL operations and commit or undo them in the autonomous transaction, and then resume the calling transaction.
  The autonomous transaction does not see uncommitted changes made by the main transaction 
  and does not share locks or resources with the main transaction.
  When you enter the executable section of an autonomous routine, the main routine suspends. 
  When you exit the autonomous routine, the main routine resumes.

COMMIT
  Use the COMMIT statement to end your current transaction and make permanent all changes performed in the transaction. 
  A transaction is a sequence of SQL statements that Oracle Database treats as a single unit. 
  This statement also erases all savepoints in the transaction and releases transaction locks.

ROLLBACK
  Use the ROLLBACK statement to undo work done in the current transaction or to manually undo the work done by an in-doubt distributed transaction.

It looks like that COMMIT / ROLLBACK are for transactions.

In this Blog, we will make two demonstrations. The first one will show that COMMIT/ROLLBACK has to be executed even without any transactions.

The test code is also trying to reproduce and study MOS:
    Bug 26965236 : DELETE FROM TSDP_SENSITIVE_DATA$ CAUSING ENQ: TM - CONTENTION WAITS

The second one is about TX and TM Locks without Transaction Visible.

Note: Tested in Oracle 12c and 19c.

1. TM lock and no transaction commit

In Oracle 12c, when you execute:

  alter table ttx drop column colx;

It will trigger an internal delete statement:

  delete from tsdp_sensitive_data$ where obj# = :1 and col_argument# = :2

even you don't use TSDP (Transparent Sensitive Data Protection).

Note: All tests are done in Oracle 12.1.0.2.

Now we can start TM lock test on above TSDP tables.

------------------ T0: Test SetUp ------------------ 
drop table tt1;

create table tt1 (x number, c1 number, c2 number);

------------------ T1: Session_1------------------ 
SQL(sid 190) > delete from sys.tsdp_sensitive_data$ where 1=2; 
  0 rows deleted.

------------------ T2: Session_2 ------------------ 
SQL(sid 290) > alter table tt1 drop column c2;

-- Session 290 hanging, blocked by 190.
-- same for   alter table k.tt1 set unused (c1);

------------------ T3: Monitor Session_3 ------------------ 
SQL(sid 390) > select o.object_name, k.* from v$lock k, dba_objects o where k.type in ('TM') and k.ID1 = o.object_id;
 
  OBJECT_NAME                    SID  TYPE  ID1      ID2  LMODE  REQUEST  CTIME  BLOCK
  -----------------------------  ---  ----  -------  ---  -----  -------  -----  -----
  TSDP_SENSITIVE_DATA$           190  TM    1576498  0    3      0        14     0    
  TSDP_SUBPOL$                   190  TM    1578689  0    3      0        14     0    
  TSDP_PROTECTION$               190  TM    1578695  0    3      0        14     1    
  TT1                            290  TM    2321087  0    6      0        9      0    
  WRI$_OPTSTAT_HISTHEAD_HISTORY  290  TM    601844   0    3      0        9      0    
  WRI$_OPTSTAT_HISTGRM_HISTORY   290  TM    601856   0    3      0        9      0    
  COM$                           290  TM    136      0    3      0        9      0    
  COL_USAGE$                     290  TM    456      0    3      0        9      0    
  OBJAUTH$                       290  TM    61       0    3      0        9      0    
  TSDP_SENSITIVE_DATA$           290  TM    1576498  0    3      0        9      0    
  TSDP_SUBPOL$                   290  TM    1578689  0    3      0        9      0    
  TSDP_PROTECTION$               290  TM    1578695  0    0      5        9      0    

--TSDP_PROTECTION$  REQUEST = 5
--Session_2 blocked by Session_1 in 'enq: TM - contention' Lock Mode 5 (SSX/SRX)

SQL(sid 390) > select * from v$transaction;
  0 rows selected.
  
  -- no TRX

SQL(sid 390) > select chain_signature, sid, blocker_sid, wait_event_text, p1, p1_text, p2, p2_text, p3, p3_text from v$wait_chains;

  CHAIN_SIGNATURE                                        SID  BLOCKER_SID  WAIT_EVENT_TEXT              P1          P1_TEXT    P2       P2_TEXT   P3  P3_TEXT
  -----------------------------------------------------  ---  -----------  ---------------------------  ----------  ---------  -------  --------  --  ---------------
  'SQL*Net message from client'<='enq: TM - contention'  290  190          enq: TM - contention         1414332421  name|mode  1578695  object #  0   table/partition
  'SQL*Net message from client'<='enq: TM - contention'  190               SQL*Net message from client  1413697536  driver id  1        #bytes    0


SQL(sid 390) > select * from dba_constraints where constraint_name = 'TSDP_PROTECTION$FKSD';

  OWNER  CONSTRAINT_NAME       CONSTRAINT_TYPE  TABLE_NAME        R_CONSTRAINT_NAME       DELETE_RULE  STATUS
  -----  --------------------  ---------------  ----------------  ----------------------  -----------  ------
  SYS    TSDP_PROTECTION$FKSD  R                TSDP_PROTECTION$  TSDP_SENSITIVE_DATA$PK  CASCADE      ENABLED


-- Suspending LGWR will not block commit in Session_1
--SQL> oradebug setorapid 13
--  Oracle pid: 13, Unix process pid: 18482, image: oracle@testdb (LGWR)
--SQL> oradebug suspend
--SQL> oradebug resume

------------------ T4: Session_1, Release TM Locks to deblock ------------------ 
SQL(sid 290) > commit;

One quick workaround is to disable the foreign key constraint if TSDP is not used.

  alter table sys.tsdp_protection$ disable constraint tsdp_protection$fksd;

or create an index if TSDP is used.

  create index sys.tsdp_protection$sensitiv on sys.tsdp_protection$(sensitive#);

If we suspend LGWR in Session_3 (see commented-out code), and repeat the whole test, the "commit" in Session_1 will not be blocked. It indicates no "commit record" written to redo log for this "commit" execution, in other words, not every "commit" generates a "commit record".

With event 10704, we can list all triggered TM Locks. (see Blog: Investigating Oracle lock issues with event 10704 )

SQL(sid 290) > alter session set events='10046 trace name context forever, level 1 : 10704 trace name context forever, level 3' tracefile_identifier='ksun_10704_1';

SQL(sid 290) > alter table tt1 drop column c1;

SQL(sid 290) > alter session set events='10046 trace name context off : 10704 trace name context off ';


ksqgtl *** TM-00236ABF-00000000-00000000-00000000 mode=6 flags=0x400 timeout=5 ***
...
ksqgtl *** TM-001816C7-00000000-00000000-00000000 mode=5 flags=0x400 timeout=21474836 ***
ksqcnv: TM-001816C7-00000000-00000000-00000000 mode=3 timeout=21474836
ksqcmi: TM-001816C7-00000000-00000000-00000000 mode=3 timeout=21474836
ksqrcl: TM-001816C7-00000000-00000000-00000000
...
ksqrcl: TM-00236ABF-00000000-00000000-00000000

  -- 00236ABF (2321087) = TT1
  -- 001816C7 (1578695) = SYS.TSDP_PROTECTION$
  
  -- ksqgtl: get lock (kernel subroutine: ksqgtlctx)
  -- ksqcnv: convert lock
  -- ksqcmi: change mode internal
  -- ksqrcl: release lock

We can see that DDL_LOCK_TIMEOUT = 5 seconds has no effect in this case (line with "TM-00236ABF" for TT1). TM lock on SYS.TSDP_PROTECTION$ ("TM-001816C7") is first obtained in MODE 5 (SRX) by ksqgtl, then converted to 3 (RX) by ksqcnv and ksqcmi, finally released by ksqrcl.

2. TX & TM Locks and No Transaction Visible

In this section, we will show one case, in which there are TX and TM locks (v$lock), but no visible transaction (v$transaction).

2.1 Test Setup

We create 2 tables and 3 Plsql programs.

drop table test_tab_1;
drop table test_tab_2;
create table test_tab_1 as select 1 x from dual;
create table test_tab_2 as select 2 x from dual;

create or replace procedure prt (p_name varchar2) as
  l_trx_cnt number;
begin
  dbms_output.put_line('===============' ||p_name||' at '||localtimestamp||'===============' );
  for cm in (select sid from v$mystat where rownum=1) loop
    for c in (select s.sid, s.serial#, s.saddr, t.addr, t.start_time, t.start_scn, 
                     t.xid, t.xidusn, t.xidslot, t.xidsqn 
               from v$session s, v$transaction t where s.taddr=t.addr(+) and s.sid=cm.sid) loop
      dbms_output.put_line(' ----1.----- Session');
      dbms_output.put_line('  sid='||c.sid||', serial#='||c.serial#||', saddr='||c.saddr);
      dbms_output.put_line(' ----2.----- Transaction');
      if c.xid is null then
        dbms_output.put_line('    ****** No Transaction Visible ******');
      else
        dbms_output.put_line('  addr='||c.addr||', start_time='||c.start_time||', start_scn='||c.start_scn||
                             ', xid='||c.xid||', xidusn='||c.xidusn||', xidslot='||c.xidslot||', xidsqn='||c.xidsqn);
      end if;
    end loop;
    
    dbms_output.put_line(' ----3.----- Locks');
    for c in (select addr, kaddr, sid, type, id1, id2, lmode, request, ctime, block
               from v$lock where type in ('TM', 'TX') and sid = cm.sid order by type) loop
      dbms_output.put('  addr='||c.addr||', kaddr='||c.kaddr||', sid='||c.sid||', type='||c.type);
      dbms_output.put(', id1='||c.id1);
      if c.type = 'TX' then
        dbms_output.put('(rbs='||trunc(c.id1/power(2,16))||', slot='||bitand(c.id1,to_number('ffff','xxxx'))||')');
      end if;
      dbms_output.put(', id2='||c.id2||', lmode='||c.lmode);
      dbms_output.put_line(', request='||c.request||', ctime='||c.ctime||', block='||c.block);
    end loop;
  end loop;
end;
/

create or replace function retx (p_x number, p_sleep_seconds number) return number as
begin
  prt('retx');
  dbms_lock.sleep(p_sleep_seconds); 
  return p_x;
end;
/

create or replace procedure update_tab_1 (p_sleep_seconds number)as
  pragma autonomous_transaction;
begin
  prt('Start autonomous_TRX'); 
  update test_tab_1 set x=retx(x, p_sleep_seconds); -- two TX and TM locks
  commit;  
    -- autonomous_transaction have to commit/rollback, 
    -- otherwise: ORA-06519: active autonomous transaction detected and rolled back
end;
/

2.2 Case1 - TX and TM Locks without Transaction Visible

Open a Sqlplus session and run test below with 10046 and 10704 trace. In the main transaction, we update test_tab_2, and in autonomous_transaction, we update test_tab_1.

alter session set events='10046 trace name context forever, level 1 : 10704 trace name context forever, level 3' 
                    tracefile_identifier='10704_trx_3';
begin 
  prt('Start Main Trx');
  update test_tab_2 set x=retx(x, 3);
  update_tab_1(6);
  commit;
end;
/

alter session set events='10046 trace name context off : 10704 trace name context off '; 

Here the test output:

===============Start Main Trx at 14-MARCH-2018 14:03:43===============
 ----1.----- Session
  sid=16, serial#=48272, saddr=000000018FCFA770
 ----2.----- Transaction
    ****** No Transaction Visible ******
 ----3.----- Locks
===============retx at 14-MARCH-2018 14:03:43===============
 ----1.----- Session
  sid=16, serial#=48272, saddr=000000018FCFA770
 ----2.----- Transaction
  addr=0000000186678CE8, start_time=05/14/20 14:03:43, start_scn=9447196146707, xid=030010006E629B00, xidusn=3, xidslot=16, xidsqn=10183278
 ----3.----- Locks
  addr=FFFF80FFBC14C4F0, kaddr=FFFF80FFBC14C558, sid=16, type=TM, id1=2468649, id2=0, lmode=3, request=0, ctime=0, block=0
  addr=0000000186678CE8, kaddr=0000000186678D68, sid=16, type=TX, id1=196624(rbs=3, slot=16), id2=10183278, lmode=6, request=0, ctime=0, block=0

===============Start autonomous_TRX at 14-MARCH-2018 14:03:47===============
 ----1.----- Session
  sid=16, serial#=48272, saddr=000000018FCFA770
 ----2.----- Transaction
    ****** No Transaction Visible ******
 ----3.----- Locks
  addr=FFFF80FFBC148410, kaddr=FFFF80FFBC148478, sid=16, type=TM, id1=2468649, id2=0, lmode=3, request=0, ctime=3, block=0
  addr=0000000186678CE8, kaddr=0000000186678D68, sid=16, type=TX, id1=196624(rbs=3, slot=16), id2=10183278, lmode=6, request=0, ctime=3, block=0
===============retx at 14-MARCH-2018 14:03:47===============
 ----1.----- Session
  sid=16, serial#=48272, saddr=000000018FCFA770
 ----2.----- Transaction
  addr=0000000184F54338, start_time=05/14/20 14:03:46, start_scn=9447196146719, xid=06002000BDADD700, xidusn=6, xidslot=32, xidsqn=14134717
 ----3.----- Locks
  addr=FFFF80FFBC139448, kaddr=FFFF80FFBC1394B0, sid=16, type=TM, id1=2468648, id2=0, lmode=3, request=0, ctime=0, block=0
  addr=FFFF80FFBC139448, kaddr=FFFF80FFBC1394B0, sid=16, type=TM, id1=2468649, id2=0, lmode=3, request=0, ctime=3, block=0
  addr=0000000184F54338, kaddr=0000000184F543B8, sid=16, type=TX, id1=393248(rbs=6, slot=32), id2=14134717, lmode=6, request=0, ctime=0, block=0
  addr=0000000186678CE8, kaddr=0000000186678D68, sid=16, type=TX, id1=196624(rbs=3, slot=16), id2=10183278, lmode=6, request=0, ctime=3, block=0

There are two lines of "****** No Transaction Visible ******".

The first one has no Transaction and no Locks:

 ----2.----- Transaction
    ****** No Transaction Visible ******
 ----3.----- Locks

However the second one has no Transaction, but has one TM lock and one TX lock:

 ----2.----- Transaction
    ****** No Transaction Visible ******
 ----3.----- Locks
  addr=FFFF80FFBC148410, kaddr=FFFF80FFBC148478, sid=16, type=TM, id1=2468649, id2=0, lmode=3, request=0, ctime=3, block=0
  addr=0000000186678CE8, kaddr=0000000186678D68, sid=16, type=TX, id1=196624(rbs=3, slot=16), id2=10183278, lmode=6, request=0, ctime=3, block=0

Under "retx at 14-MARCH-2018 14:03:43", there is one transaction:

 ----2.----- Transaction
  addr=0000000186678CE8, start_time=05/14/20 14:03:43, start_scn=9447196146707, xid=030010006E629B00, xidusn=3, xidslot=16, xidsqn=10183278

but 3 seconds later (we sleep 3 seconds), when we step into autonomous_transaction without any commit/rollback, the transaction is no more visible as showed under line: "Start autonomous_TRX at 14-MARCH-2018 14:03:47"

 ----2.----- Transaction
    ****** No Transaction Visible ******

Here the output of 10046 and 10704 trace (unrelated lines removed)

*** 2018-03-14 14:03:43.937
begin
  prt('Start Main Trx');
  update test_tab_2 set x=retx(x, 3);
  update_tab_1(6);
  commit;
end;

UPDATE TEST_TAB_2 SET X=RETX(X, 3)
ksqgtl *** TM-0025AB29-00000000-00000000-00000000 mode=3 flags=0x400 timeout=21474836 ***
ksqgtl *** TX-00030010-009B626E-00000000-00000000 mode=6 flags=0x401 timeout=0 ***

*** 2018-03-14 14:03:47.019
UPDATE TEST_TAB_1 SET X=RETX(X, :B1 )
ksqgtl *** TM-0025AB28-00000000-00000000-00000000 mode=3 flags=0x400 timeout=21474836 ***
ksqgtl *** TX-00060020-00D7ADBD-00000000-00000000 mode=6 flags=0x401 timeout=0 ***

ksqrcl: TX-00060020-00D7ADBD-00000000-00000000
ksqrcl: TM-0025AB28-00000000-00000000-00000000

ksqrcl: TX-00030010-009B626E-00000000-00000000
ksqrcl: TM-0025AB29-00000000-00000000-00000000

2.3 Case2 - TX and TM Locks without Transaction Visible, and Deadlock

In the above test, we first update test_tab_2, then update test_tab_1 (in procedure update_tab_1). If we make both updates on the same table: test_tab_1 as follows:

begin 
  prt('Start Main Trx');
  update test_tab_1 set x=retx(x, 3);
  update_tab_1(6);
  commit;
end;
/

In the test output, there are also two lines of "****** No Transaction Visible ******" as above, in which the second one shows no Transaction, but one TM lock and one TX lock.

In addition to that, it throws "ORA-00060: deadlock".

===============Start Main Trx at 14-MARCH-2018 14:16:33===============
 ----1.----- Session
  sid=550, serial#=28708, saddr=00000000B8D16608
 ----2.----- Transaction
    ****** No Transaction Visible ******
 ----3.----- Locks
===============retx at 14-MARCH-2018 14:16:33===============
 ----1.----- Session
  sid=550, serial#=28708, saddr=00000000B8D16608
 ----2.----- Transaction
  addr=00000000AD763D60, start_time=05/14/20 14:16:32, start_scn=9684875117947, xid=6800100069270000, xidusn=104, xidslot=16, xidsqn=10089
 ----3.----- Locks
  addr=00007F758AA7EAC0, kaddr=00007F758AA7EAE8, sid=550, type=TM, id1=3307704, id2=0, lmode=3, request=0, ctime=0, block=0
  addr=00000000AD763D60, kaddr=00000000AD763D98, sid=550, type=TX, id1=6815760(rbs=104, slot=16), id2=10089, lmode=6, request=0, ctime=0, block=0

===============Start autonomous_TRX at 14-MARCH-2018 14:16:36===============
 ----1.----- Session
  sid=550, serial#=28708, saddr=00000000B8D16608
 ----2.----- Transaction
    ****** No Transaction Visible ******
 ----3.----- Locks
  addr=00007F758AA72BA0, kaddr=00007F758AA72BC8, sid=550, type=TM, id1=3307704, id2=0, lmode=3, request=0, ctime=3, block=0
  addr=00000000AD763D60, kaddr=00000000AD763D98, sid=550, type=TX, id1=6815760(rbs=104, slot=16), id2=10089, lmode=6, request=0, ctime=3, block=0
begin
*
ERROR at line 1:
ORA-00060: deadlock detected while waiting for resource
ORA-06512: at "S.UPDATE_TAB_1", line 5
ORA-06512: at line 4

Here the "ORA-00060: deadlock" trace file, which contains Deadlock graph and call stack (subroutine "ksqgtlctx" is for "ksqgtl" in 10704 trace).

Deadlock graph:
                                       ------------Blocker(s)-----------  ------------Waiter(s)------------
Resource Name                          process session holds waits serial  process session holds waits serial
TX-00680010-00002769-00000000-00000000      57     550     X        28708      57     550           X  28708

0: waiting for 'enq: TX - row lock contention'
   name|mode=0x54580006, usn<<16 | slot=0x680010, sequence=0x2769

xid:  0x0068.010.00002769 

------- Binary Stack Dump --------

   [1]  (ksedst1()+95 -> kgdsdst())
   [2]  (ksedst()+58 -> ksedst1())
   [3]  (dbkedDefDump()+23080 -> ksedst())
   [4]  (ksedmp()+577 -> dbkedDefDump())
   [5]  (ksqdld_hdr_dump()+4900 -> ksedmp())
   [6]  (ksqcmi()+25602 -> ksqdld_hdr_dump())
   [7]  (ksqgtlctx()+6620 -> ksqcmi())
   [8]  (ksqgelctx()+838 -> ksqgtlctx())
   [9]  (ktuGetTxForXid()+324 -> ksqgelctx())
   [10] (ktcwit1()+367 -> ktuGetTxForXid())
   [11] (kdddgb()+5478 -> ktcwit1())
   [12] (kdusru()+458 -> kdddgb())
   [13] (kauupd()+356 -> kdusru())
   [14] (updrow()+1699 -> kauupd())
   [15] (qerupUpdRow()+725 -> updrow())
   [16] (qerupRopRowsets()+259 -> qerupUpdRow())
   [17] (kdstf000110100001000km()+1757 -> qerupRopRowsets())
   [18] (kdsttgr()+2154 -> kdstf000110100001000km())
   [19] (qertbFetch()+1089 -> kdsttgr())
   [20] (qerupFetch()+532 -> qertbFetch())
   [21] (updaul()+1416 -> qerupFetch())
   [22] (updThreePhaseExe()+340 -> updaul())
   [23] (updexe()+443 -> updThreePhaseExe())
   [24] (opiexe()+11815 -> updexe())

In fact, in the above tests, if repeatedly running query below during the test, we can also see two TM and TX locks, but XID is null. Immediately before session raising "ORA-00060: deadlock", the same session holds TX in LMODE=6, but still make REQUEST=6, hence BLOCK=1, a typical cyclic deadlock.

SQL > select s.sid, l.*, t.xid 
      from v$session s, v$lock l, v$transaction t 
      where s.sid=l.sid and s.taddr=t.addr(+) and s.sid = 550;

  SID ADDR             KADDR            SID TY      ID1   ID2 LMODE REQUEST CTIME BLOCK  XID
  --- ---------------- ---------------- --- -- -------- ----- ----- ------- ----- -----  ---
  550 00007F80B92BC410 00007F80B92BC438 550 TM  3307704     0     3       0     6     0 
  550 00007F80B92BC410 00007F80B92BC438 550 TM  3307704     0     3       0     3     0 
  550 00000000B5B9B958 00000000B5B9B988 550 AE      100     0     4       0  5019     0 
  550 00000000B5B9DE30 00000000B5B9DE60 550 TX  7012376 16581     0       6     3     0 
  550 00000000AD67B2C0 00000000AD67B2F8 550 TX  7012376 16581     6       0     6     1 

For Oracle applications, it means that we cannot rely on v$transaction to determine the existence of Oracle transactions, as well as TX and TM Locks. There are the time period, in which transactions are hidden, thus not visible in v$transaction.