Blocking Session not visible in v$ Views
By Martin | February 16th, 2018 | Category: 11gR2, JDBC, Oracle Database | No Comments »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…
