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.<\/p>\n
In the system state dump, there was a reference for the hanging session: 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.<\/p>\n 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\". <\/p>\n After some research I found this note: <\/p>\n Solving locking problems in a XA environment ( Doc ID 1248848.1 )<\/p><\/blockquote>\n 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.<\/p>\n No entry in DBA_2PC_PENDING but the Query from MOS Note shows Active XA Trans:<\/p>\n 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.<\/p>\n With Redo Log Mining for the transaction ID, we could get some minor details about the session which initially opened this global transaction. <\/p>\n 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...<\/p>\n","protected":false},"excerpt":{"rendered":" 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 […]<\/p>\n","protected":false},"author":2,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"_monsterinsights_skip_tracking":false,"_monsterinsights_sitenote_active":false,"_monsterinsights_sitenote_note":"","_monsterinsights_sitenote_category":0,"footnotes":""},"categories":[57,55,5],"tags":[],"class_list":["post-1497","post","type-post","status-publish","format-standard","hentry","category-11gr2","category-jdbc","category-oracle-database"],"aioseo_notices":[],"_links":{"self":[{"href":"https:\/\/www.ora-solutions.net\/web\/wp-json\/wp\/v2\/posts\/1497","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/www.ora-solutions.net\/web\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/www.ora-solutions.net\/web\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/www.ora-solutions.net\/web\/wp-json\/wp\/v2\/users\/2"}],"replies":[{"embeddable":true,"href":"https:\/\/www.ora-solutions.net\/web\/wp-json\/wp\/v2\/comments?post=1497"}],"version-history":[{"count":12,"href":"https:\/\/www.ora-solutions.net\/web\/wp-json\/wp\/v2\/posts\/1497\/revisions"}],"predecessor-version":[{"id":1510,"href":"https:\/\/www.ora-solutions.net\/web\/wp-json\/wp\/v2\/posts\/1497\/revisions\/1510"}],"wp:attachment":[{"href":"https:\/\/www.ora-solutions.net\/web\/wp-json\/wp\/v2\/media?parent=1497"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.ora-solutions.net\/web\/wp-json\/wp\/v2\/categories?post=1497"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.ora-solutions.net\/web\/wp-json\/wp\/v2\/tags?post=1497"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}SQL> oradebug setmypid
\nSQL> oradebug unlimit;
\nSQL> select * from dual;
\nSQL> oradebug dump systemstate 258
\nSQL> oradebug dump systemstate 258 <\/code><\/p>\n
\n
\nWaiter:<\/strong><\/p>\n\r\n ----------------------------------------\r\n SO: 0x000000075C68F8B8, type: 2, owner: 0x0000000000000000, flag: INIT\/-\/-\/0x00 if: 0x3 c: 0x3\r\n proc=0x000000075C68F8B8, name=process, file=ksu.h LINE:12740, pg=0\r\n (process) Oracle pid:161, ser:247, calls cur\/top: 0x000000075BC6A370\/0x000000075BC6A370\r\n flags : (0x0) -\r\n flags2: (0x0), flags3: (0x10) \r\n intr error: 0, call error: 0, sess error: 0, txn error 0\r\n intr queue: empty\r\n ksudlp FALSE at location: 0\r\n (post info) last post received: 0 0 0\r\n last post received-location: No post\r\n last process to post me: none\r\n last post sent: 0 0 0\r\n last post sent-location: No post\r\n last process posted by me: none\r\n (latch info) wait_event=0 bits=0x0\r\n Process Group: DEFAULT, pseudo proc: 0x000000076068CE68\r\n O\/S info: user: SYSTEM, term: HOSTNAME, ospid: 4600 \r\n OSD pid info: Windows thread id: 4600, image: ORACLE.EXE (SHAD)\r\n Short stack dump: \r\nksedsts()+585<-ksdxfstk()+44<-ksdxcb()+2402<-ssthreadsrgruncallback()+629<-OracleOradebugThreadStart()+829\r\n<-0000000076D559CD<-0000000076E8A561<-0000000076EABD7A<-000007FEFCE910AC<-skgpwwait()+182<-ksliwat()+2459\r\n<-kslwaitctx()+184<-ksqcmi()+7848<-ksqgtlctx()+6814<-ksqgelctx()+829<-ktuGetTxForXid()+190<-ktcwit1()+526\r\n<-kdddgb()+9636<-kddlkr()+284<-qerfuProcessFetchedRow()+1019<-__PGOSF308_qerfuLockingRowProcedure()+89\r\n<-qertbFetchByRowID()+2708<-qerfuStart()+590<-selexe0()+3495<-opiexe()+22377<-kpoal8()+2624<-opiodr()+1646\r\n<-ttcpip()+1481<-opitsk()+2166<-opiino()+1246<-opiodr()+1646<-opidrv()+862<-sou2o()+98<-opimai_real()+158\r\n<-opimai()+191<-OracleThreadStart()+724<-0000000076D559CD<-0000000076E8A561\r\n01-04-2018 21:16:06.636\r\n ----------------------------------------\r\n SO: 0x00000007606D9B88, type: 4, owner: 0x000000075C68F8B8, flag: INIT\/-\/-\/0x00 if: 0x3 c: 0x3\r\n proc=0x000000075C68F8B8, name=session, file=ksu.h LINE:12748, pg=0\r\n (session) sid: 68 ser: 20263 trans: 0x0000000755DB9838, creator: 0x000000075C68F8B8\r\n flags: (0x41) USR\/- flags_idl: (0x1) BSY\/-\/-\/-\/-\/-\r\n flags2: (0x40009) -\/-\/INC\r\n DID: , short-term DID: \r\n txn branch: 0x0000000000000000\r\n edition#: 100 oct: 3, prv: 0, sql: 0x00000007708AA2E8, psql: 0x000000076BDCDED8, user: 0\/SYS\r\n ksuxds FALSE at location: 0\r\n service name: SYS$USERS\r\n client details:\r\n O\/S info: user: username, term: hostname, ospid: 5968:4960\r\n machine: hostname program: sqlplus.exe\r\n application name: sqlplus.exe, hash value=254292535\r\n Current Wait Stack:\r\n 0: waiting for 'enq: TX - row lock contention'\r\n name|mode=0x54580006, usn<<16 | slot=0x130009, sequence=0xb394f\r\n wait_id=10 seq_num=11 snap_id=1\r\n wait times: snap=8 min 15 sec, exc=8 min 15 sec, total=8 min 15 sec\r\n wait times: max=infinite, heur=8 min 15 sec\r\n wait counts: calls=166 os=166\r\n in_wait=1 iflags=0x15a0\r\n Wait State:\r\n fixed_waits=0 flags=0x22 boundary=0x0000000000000000\/-1\r\n...\r\n ----------------------------------------\r\n SO: 0x0000000778A7FCA8, type: 8, owner: 0x000000075BC6A370, flag: INIT\/-\/-\/0x00 if: 0x1 c: 0x1\r\n proc=0x000000075C68F8B8, name=enqueue, file=ksq1.h LINE:380, pg=0\r\n (enqueue) TX-00130009-000B394F\tDID: 0001-00A1-0003F59C\r\n lv: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 res_flag: 0x6\r\n req: X, lock_flag: 0x10, lock: 0x0000000778A7FD00, res: 0x0000000760A2BD80\r\n own: 0x00000007606D9B88, sess: 0x00000007606D9B88, proc: 0x000000075C68F8B8, prv: 0x0000000760A2BDA0\r\n ----------------------------------------\r\n<\/pre>\n
\r\nPSEUDO PROCESS for group DEFAULT:\r\n ----------------------------------------\r\n SO: 0x000000076068CE68, type: 2, owner: 0x0000000000000000, flag: INIT\/-\/-\/0x00 if: 0x3 c: 0x3\r\n proc=0x000000076068CE68, name=process, file=ksu.h LINE:12740, pg=0\r\n (process) Oracle pid:0, ser:0, calls cur\/top: 0x0000000000000000\/0x0000000000000000\r\n flags : (0x20) PSEUDO\r\n flags2: (0x0), flags3: (0x0) \r\n intr error: 0, call error: 0, sess error: 0, txn error 0\r\n intr queue: empty\r\n ksudlp FALSE at location: 0\r\n (post info) last post received: 0 0 0\r\n last post received-location: No post\r\n last process to post me: none\r\n last post sent: 0 0 0\r\n last post sent-location: No post\r\n last process posted by me: none\r\n (latch info) wait_event=0 bits=0x0\r\n Process Group: DEFAULT, pseudo proc: 0x000000076068CE68\r\n O\/S info: user: , term: , ospid: (DEAD)\r\n OSD pid info: Windows thread id: 0, image: PSEUDO\r\n PSO child state object changes :\r\nDump of memory from 0x00000007605E5698 to 0x00000007605E58A0\r\n7605E5690 00000000 00000000 [........]\r\n7605E56A0 00000000 00000000 00000000 00000000 [................]\r\n Repeat 31 times\r\nBEGIN DUMP RESERVED PROCESSES\r\nEND DUMP RESERVED PROCESSES\r\nDETACHED BRANCHES:\r\n----------------------------------------\r\nSO: 0x0000000755E7C0F0, type: 58, owner: 0x0000000000000000, flag: INIT\/-\/-\/0x00 if: 0x3 c: 0x3\r\n proc=0x0000000000000000, name=branch, file=ktccts.h LINE:420, pg=0\r\n(branch) trn = 0x0000000000000000, flg = 0x40, state = 0x00 bno=0 ser=0 evt=0\r\n..\r\n SO: 0x0000000755E2B378, type: 58, owner: 0x0000000755E7C0F0, flag: INIT\/-\/-\/0x00 if: 0x3 c: 0x3\r\n proc=0x000000077860EB80, name=branch, file=ktccts.h LINE:420, pg=0\r\n (branch) trn = 0x0000000755E01068, flg = 0x41090, state = 0x00 bno=1 ser=10 evt=10\r\n creator = 0x00000007607940E8 uid = 0x42 serial# = 7929 ttl = 0x15180 dtm = 0x5a4db9f5\r\n 2PCrole = (nch = 0x0 flg = 0x0) DTP svc = 0x773ffc978\r\n...\r\n SO: 0x0000000755E01068, type: 56, owner: 0x0000000755E2B378, flag: INIT\/-\/-\/0x00 if: 0x3 c: 0x3\r\n proc=0x000000077860EB80, name=transaction, file=ktccts.h LINE:410, pg=0\r\n (trans) flg = 0x00401e03, flg2 = 0x04080000, flg3 = 0x00000000, prx = 0x0000000000000000, ros = 2147483647, crtses=0x00000007607940E8\r\n...\r\n (enqueue) TX-00130009-000B394F\tDID: 0001-00E6-000010CD\r\n lv: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 res_flag: 0x6\r\n mode: X, lock_flag: 0x0, lock: 0x0000000755E010E0, res: 0x0000000760A2BD80\r\n own: 0x0000000755E01068 (TXN), sess: 0x0000000000000000, prv: 0x0000000760A2BD90\r\n<\/pre>\n
\r\nselect --+ ORDERED\r\n'----------------------------------------'||'\r\nCurent Time : '|| substr(to_char(sysdate,' HH24.MI.SS'),1,22) ||'\r\n'||'TX start_time: '||t.KTCXBSTM||'\r\n'||'FORMATID: '||g.K2GTIFMT ||'\r\n'||'GTXID: '||g.K2GTITID_EXT ||'\r\n'||'Branch: '||g.K2GTIBID ||'\r\nLocal_Tran_Id ='||substr(t.KXIDUSN||'.'||t.kXIDSLT||'.'||t.kXIDSQN,1,15)||'\r\n'||'KTUXESTA='|| x.KTUXESTA ||'\r\n'||'KTUXEDFL='|| x.KTUXECFL ||'\r\nLock_Info: ID1: ' || ((t.kXIDUSN*64*1024)+ t.kXIDSLT)\r\n||' ID2: '|| t.kXIDSQN\r\nXA_transaction_INFO\r\nfrom x$k2gte g, x$ktcxb t, x$ktuxe x\r\nwhere g.K2GTDXCB =t.ktcxbxba and\r\nx.KTUXEUSN = t.KXIDUSN(+) and\r\nx.KTUXESLT = t.kXIDSLT(+) and\r\nx.KTUXESQN =t.kXIDSQN(+);\r\n\r\n\"----------------------------------------\r\nCurent Time : 11.35.27\r\nTX start_time: 02\/05\/18 15:35:17\r\nFORMATID: 131075\r\nGTXID: 312D613331303063613A653165623A35613732336438373A31326335323962\r\nBranch: 613331303063613A653165623A35613732336438373A31326335326166\r\nLocal_Tran_Id =25.18.61640\r\nKTUXESTA=ACTIVE\r\nKTUXEDFL=NONE\r\nLock_Info: ID1: 1638418 ID2: 61640\"\r\n\"----------------------------------------\r\nCurent Time : 11.35.27\r\nTX start_time: 02\/05\/18 15:35:17\r\nFORMATID: 131075\r\nGTXID: 312D613331303063613A653165623A35613732336438373A31326335326135\r\nBranch: 613331303063613A653165623A35613732336438373A31326335326165\r\nLocal_Tran_Id =16.26.2292874\r\nKTUXESTA=ACTIVE\r\nKTUXEDFL=NONE\r\nLock_Info: ID1: 1048602 ID2: 2292874\"\r\n\"----------------------------------------\r\nCurent Time : 11.35.27\r\nTX start_time: 02\/05\/18 15:35:17\r\nFORMATID: 131075\r\nGTXID: 312D613331303063613A653165623A35613732336438373A31326335326161\r\nBranch: 613331303063613A653165623A35613732336438373A31326335326232\r\nLocal_Tran_Id =3.30.3767984\r\nKTUXESTA=ACTIVE\r\nKTUXEDFL=NONE\r\nLock_Info: ID1: 196638 ID2: 3767984\"\r\n<\/pre>\n
\r\nset JAVA_HOME=c:\\oracle\\product\\11.2.0.4\\dbhome_1\\jdk\\jre\r\nset CLASSPATH=c:\\dba\\scripts\\;c:\\oracle\\product\\11.2.0.4\\dbhome_1\\jdbc\\lib\\ojdbc5.jar:%CLASSPATH%\r\nC:\\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\r\n++ URL: jdbc:oracle:thin:@hostname:1521:PROD\r\n++ Rollback of Local_tran_ID : 25.18.61640\r\n++ got XA resource handle\r\n++ got Connection handle\r\n++ 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\r\nSLT(+) and x.KTUXESQN =t.KXIDSQN(+) and t.KXIDUSN=25 and t.kXIDSLT=18 and t.kXIDSQN= 61640\r\n++ Getting XID for Local_Tran_ID: 25.18.61640\r\n+ Found global XID: -->\r\n++ Format Id: 131075\r\n++ Group Id: 312D613331303063613A653165623A35613732336438373A31326335323962\r\n++ Branch Id: 613331303063613A653165623A35613732336438373A31326335326166\r\n\r\n-> Would your really like to continue (yes or no):\r\nyes\r\n... doing Rollback\r\n\r\n... Rollback done ! \r\n<\/pre>\n