Blocking Session not visible in v$ Views

I had to troubleshoot an issue on a company ERP systems database, where several sessions were waiting for ‘enq: TX row lock contention’. It was a table containing print server nodes and this caused no more printouts. Usually troubleshooting locking issues is quite straightforward in recent versions of oracle database, but this time, the column “v$session.blocking_session” was not populated and there was no entry in v$lock for the blocker. This was strange, so I involved Oracle Support. They requested a system state dump.

SQL> oradebug setmypid
SQL> oradebug unlimit;
SQL> select * from dual;
SQL> oradebug dump systemstate 258
SQL> oradebug dump systemstate 258

In the system state dump, there was a reference for the hanging session:

Waiter:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
  ----------------------------------------
  SO: 0x000000075C68F8B8, type: 2, owner: 0x0000000000000000, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
   proc=0x000000075C68F8B8, name=process, file=ksu.h LINE:12740, pg=0
  (process) Oracle pid:161, ser:247, calls cur/top: 0x000000075BC6A370/0x000000075BC6A370
            flags : (0x0) -
            flags2: (0x0),  flags3: (0x10) 
            intr error: 0, call error: 0, sess error: 0, txn error 0
            intr queue: empty
    ksudlp FALSE at location: 0
  (post info) last post received: 0 0 0
              last post received-location: No post
              last process to post me: none
              last post sent: 0 0 0
              last post sent-location: No post
              last process posted by me: none
    (latch info) wait_event=0 bits=0x0
    Process Group: DEFAULT, pseudo proc: 0x000000076068CE68
    O/S info: user: SYSTEM, term: HOSTNAME, ospid: 4600 
    OSD pid info: Windows thread id: 4600, image: ORACLE.EXE (SHAD)
    Short stack dump: 
ksedsts()+585<-ksdxfstk()+44<-ksdxcb()+2402<-ssthreadsrgruncallback()+629<-OracleOradebugThreadStart()+829
<-0000000076D559CD<-0000000076E8A561<-0000000076EABD7A<-000007FEFCE910AC<-skgpwwait()+182<-ksliwat()+2459
<-kslwaitctx()+184<-ksqcmi()+7848<-ksqgtlctx()+6814<-ksqgelctx()+829<-ktuGetTxForXid()+190<-ktcwit1()+526
<-kdddgb()+9636<-kddlkr()+284<-qerfuProcessFetchedRow()+1019<-__PGOSF308_qerfuLockingRowProcedure()+89
<-qertbFetchByRowID()+2708<-qerfuStart()+590<-selexe0()+3495<-opiexe()+22377<-kpoal8()+2624<-opiodr()+1646
<-ttcpip()+1481<-opitsk()+2166<-opiino()+1246<-opiodr()+1646<-opidrv()+862<-sou2o()+98<-opimai_real()+158
<-opimai()+191<-OracleThreadStart()+724<-0000000076D559CD<-0000000076E8A561
01-04-2018 21:16:06.636
    ----------------------------------------
    SO: 0x00000007606D9B88, type: 4, owner: 0x000000075C68F8B8, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
     proc=0x000000075C68F8B8, name=session, file=ksu.h LINE:12748, pg=0
    (session) sid: 68 ser: 20263 trans: 0x0000000755DB9838, creator: 0x000000075C68F8B8
              flags: (0x41) USR/- flags_idl: (0x1) BSY/-/-/-/-/-
              flags2: (0x40009) -/-/INC
              DID: , short-term DID: 
              txn branch: 0x0000000000000000
              edition#: 100              oct: 3, prv: 0, sql: 0x00000007708AA2E8, psql: 0x000000076BDCDED8, user: 0/SYS
    ksuxds FALSE at location: 0
    service name: SYS$USERS
    client details:
      O/S info: user: username, term: hostname, ospid: 5968:4960
      machine: hostname program: sqlplus.exe
      application name: sqlplus.exe, hash value=254292535
    Current Wait Stack:
     0: waiting for 'enq: TX - row lock contention'
        name|mode=0x54580006, usn<<16 | slot=0x130009, sequence=0xb394f
        wait_id=10 seq_num=11 snap_id=1
        wait times: snap=8 min 15 sec, exc=8 min 15 sec, total=8 min 15 sec
        wait times: max=infinite, heur=8 min 15 sec
        wait counts: calls=166 os=166
        in_wait=1 iflags=0x15a0
    Wait State:
      fixed_waits=0 flags=0x22 boundary=0x0000000000000000/-1
...
      ----------------------------------------
      SO: 0x0000000778A7FCA8, type: 8, owner: 0x000000075BC6A370, flag: INIT/-/-/0x00 if: 0x1 c: 0x1
       proc=0x000000075C68F8B8, name=enqueue, file=ksq1.h LINE:380, pg=0
      (enqueue) TX-00130009-000B394F	DID: 0001-00A1-0003F59C
      lv: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  res_flag: 0x6
      req: X, lock_flag: 0x10, lock: 0x0000000778A7FD00, res: 0x0000000760A2BD80
      own: 0x00000007606D9B88, sess: 0x00000007606D9B88, proc: 0x000000075C68F8B8, prv: 0x0000000760A2BDA0
    ----------------------------------------

In line 60 you can see that the session is requesting an eXclusive lock for resource res: 0x0000000760A2BD80. When searching for the next appearance of res: 0x0000000760A2BD80, we find a reference to the exclusive enqueue after the last process in a section PSEUDO PROCESS / DETACHED BRANCHES.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
PSEUDO PROCESS for group DEFAULT:
  ----------------------------------------
  SO: 0x000000076068CE68, type: 2, owner: 0x0000000000000000, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
   proc=0x000000076068CE68, name=process, file=ksu.h LINE:12740, pg=0
  (process) Oracle pid:0, ser:0, calls cur/top: 0x0000000000000000/0x0000000000000000
            flags : (0x20) PSEUDO
            flags2: (0x0),  flags3: (0x0) 
            intr error: 0, call error: 0, sess error: 0, txn error 0
            intr queue: empty
    ksudlp FALSE at location: 0
  (post info) last post received: 0 0 0
              last post received-location: No post
              last process to post me: none
              last post sent: 0 0 0
              last post sent-location: No post
              last process posted by me: none
    (latch info) wait_event=0 bits=0x0
    Process Group: DEFAULT, pseudo proc: 0x000000076068CE68
    O/S info: user: , term: , ospid:  (DEAD)
    OSD pid info: Windows thread id: 0, image: PSEUDO
  PSO child state object changes :
Dump of memory from 0x00000007605E5698 to 0x00000007605E58A0
7605E5690                   00000000 00000000          [........]
7605E56A0 00000000 00000000 00000000 00000000  [................]
  Repeat 31 times
BEGIN DUMP RESERVED PROCESSES
END DUMP RESERVED PROCESSES
DETACHED BRANCHES:
----------------------------------------
SO: 0x0000000755E7C0F0, type: 58, owner: 0x0000000000000000, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
 proc=0x0000000000000000, name=branch, file=ktccts.h LINE:420, pg=0
(branch) trn = 0x0000000000000000, flg = 0x40, state = 0x00 bno=0 ser=0 evt=0
..
  SO: 0x0000000755E2B378, type: 58, owner: 0x0000000755E7C0F0, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
   proc=0x000000077860EB80, name=branch, file=ktccts.h LINE:420, pg=0
  (branch) trn = 0x0000000755E01068, flg = 0x41090, state = 0x00 bno=1 ser=10 evt=10
   creator = 0x00000007607940E8 uid = 0x42 serial# = 7929 ttl = 0x15180 dtm = 0x5a4db9f5
   2PCrole = (nch = 0x0 flg = 0x0) DTP svc = 0x773ffc978
...
    SO: 0x0000000755E01068, type: 56, owner: 0x0000000755E2B378, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
     proc=0x000000077860EB80, name=transaction, file=ktccts.h LINE:410, pg=0
    (trans) flg = 0x00401e03, flg2 = 0x04080000, flg3 = 0x00000000, prx = 0x0000000000000000, ros = 2147483647, crtses=0x00000007607940E8
...
    (enqueue) TX-00130009-000B394F	DID: 0001-00E6-000010CD
    lv: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  res_flag: 0x6
    mode: X, lock_flag: 0x0, lock: 0x0000000755E010E0, res: 0x0000000760A2BD80
    own: 0x0000000755E01068 (TXN), sess: 0x0000000000000000, prv: 0x0000000760A2BD90

The SEV1 support engineer could not be convinced that the entry DETACHED BRANCHES has nothing to do with the last session listed in the system state dump. I delivered multiple system state dumps and he insisted that the lock was always held by the very last session of the system state dump – what a coincidence. He just scrolled up from the line 46 until the first occurence of “(session)” and was convinced to have found the blocker, not realizing that he overjumped the sections “DETACHED BRANCHES”/”PSEUDO PROCESS for group DEFAULT”.

After some research I found this note:

Solving locking problems in a XA environment ( Doc ID 1248848.1 )

This note explains that with XA (distributed transactions), e.g. DB Links, there can be situations where blocker is not visible. Unfortunately, the symptoms disappeared from the production system before the diagnostic steps from the MOS Note could be tried. Frequently, when there is an issue that remains unsolved, it comes back at a later point and so it was in this case. This time, I was armed with knowledge of the MOS note 1248848.1 and could use the XA rollback script provided there to free up the “session-less” blocking lock.

No entry in DBA_2PC_PENDING but the Query from MOS Note shows Active XA Trans:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
select --+ ORDERED
'----------------------------------------'||'
Curent Time : '|| substr(to_char(sysdate,' HH24.MI.SS'),1,22) ||'
'||'TX start_time: '||t.KTCXBSTM||'
'||'FORMATID: '||g.K2GTIFMT ||'
'||'GTXID: '||g.K2GTITID_EXT ||'
'||'Branch: '||g.K2GTIBID ||'
Local_Tran_Id ='||substr(t.KXIDUSN||'.'||t.kXIDSLT||'.'||t.kXIDSQN,1,15)||'
'||'KTUXESTA='|| x.KTUXESTA ||'
'||'KTUXEDFL='|| x.KTUXECFL ||'
Lock_Info: ID1: ' || ((t.kXIDUSN*64*1024)+ t.kXIDSLT)
||' ID2: '|| t.kXIDSQN
XA_transaction_INFO
from x$k2gte g, x$ktcxb t, x$ktuxe x
where g.K2GTDXCB =t.ktcxbxba and
x.KTUXEUSN = t.KXIDUSN(+) and
x.KTUXESLT = t.kXIDSLT(+) and
x.KTUXESQN =t.kXIDSQN(+);
 
"----------------------------------------
Curent Time : 11.35.27
TX start_time: 02/05/18 15:35:17
FORMATID: 131075
GTXID: 312D613331303063613A653165623A35613732336438373A31326335323962
Branch: 613331303063613A653165623A35613732336438373A31326335326166
Local_Tran_Id =25.18.61640
KTUXESTA=ACTIVE
KTUXEDFL=NONE
Lock_Info: ID1: 1638418 ID2: 61640"
"----------------------------------------
Curent Time : 11.35.27
TX start_time: 02/05/18 15:35:17
FORMATID: 131075
GTXID: 312D613331303063613A653165623A35613732336438373A31326335326135
Branch: 613331303063613A653165623A35613732336438373A31326335326165
Local_Tran_Id =16.26.2292874
KTUXESTA=ACTIVE
KTUXEDFL=NONE
Lock_Info: ID1: 1048602 ID2: 2292874"
"----------------------------------------
Curent Time : 11.35.27
TX start_time: 02/05/18 15:35:17
FORMATID: 131075
GTXID: 312D613331303063613A653165623A35613732336438373A31326335326161
Branch: 613331303063613A653165623A35613732336438373A31326335326232
Local_Tran_Id =3.30.3767984
KTUXESTA=ACTIVE
KTUXEDFL=NONE
Lock_Info: ID1: 196638 ID2: 3767984"

This output proved that it was CASE 2: No Entry in dba_2pc_pending und Status ACTIVE. Then I could successfully avoid an instance restart and rollback the global transaction to free up the locks.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
set JAVA_HOME=c:\oracle\product\11.2.0.4\dbhome_1\jdk\jre
set CLASSPATH=c:\dba\scripts\;c:\oracle\product\11.2.0.4\dbhome_1\jdbc\lib\ojdbc5.jar:%CLASSPATH%
C:\DBA\scripts>c:\oracle\product\11.2.0.4\dbhome_1\jdk\jre\bin\java XA_rb jdbc:oracle:thin:@hostname:1521:PROD -ROLLBACK 25 18 61640
++ URL: jdbc:oracle:thin:@hostname:1521:PROD
++ Rollback of Local_tran_ID : 25.18.61640
++ got XA resource handle
++ got Connection handle
++ SQL : select g.K2GTIFMT, g.K2GTITID_EXT, g.K2GTIBID, rawtohex( g.K2GTITID_EXT), rawtohex(g.K2GTIBID) from sys.vw_x$k2gte g, sys.vw_x$ktcxb t, sys.vw_x$ktuxe x where g.K2GTDXCB =t.KTCXBXBA and x.KTUXEUSN
SLT(+) and x.KTUXESQN =t.KXIDSQN(+) and t.KXIDUSN=25 and t.kXIDSLT=18 and t.kXIDSQN= 61640
++ Getting XID for Local_Tran_ID: 25.18.61640
+ Found global XID: -->
++ Format Id: 131075
++ Group Id: 312D613331303063613A653165623A35613732336438373A31326335323962
++ Branch Id: 613331303063613A653165623A35613732336438373A31326335326166
 
-> Would your really like to continue (yes or no):
yes
... doing Rollback
 
... Rollback done !

With Redo Log Mining for the transaction ID, we could get some minor details about the session which initially opened this global transaction.

So whenever you find the strange situation that sessions are blocked on ‘enq: TX – row lock contention’ but there is no blocker in v$session blocking_session column or no entry of a session holding the lock in v$lock, then this MOS Note might be helpful in cleaning up the lock. Sadly, another case where even SEV1 support was no help at all. I have to mention however, that i recently had a SEV1 issue with an excellent and ambitious engineer. So there is still hope…

Leave Comment