RAC internals - GLOBAL ENQUEUE SERVICES DEADLOCK DETECTED
in [Oracle]
|
Prev: SP2-0332: Cannot create spool file
Next: Strange SQL
From: yong321 on 6 Nov 2005 18:16 dusan75(a)gmail.com wrote: > Yes, I have got info from Oracle that in some cases this numbers should > be related to transaction id instead of process id. However, I do not > know how it is encoded, because I'm also using Log Miner to find > offending SQL, but still with no success. :-( > > -- > Dusan Bolek Using log miner is the way to go, unless you enable SQL trace beforehand. Although it may not help solve your problem, can you ask Oracle when the number(s) is/are PIDs? It may be that with two numbers in brackets (as in your case), they're transaction IDs, and if it's a single number as in Bug:3977157, it's PID. AIX can have surprisingly high PIDs. A message at http://unix.derkeiler.com/Mailing-Lists/AIX-L/2004-02/0059.html says its max value is > 67 million. Solaris is only up to 999999 and Linux 32k. Please post back anything interesting you and Oracle support find. Thanks. Yong Huang
From: Dusan Bolek on 7 Nov 2005 02:02 The Oracle support response was: These values are: <BLOCKED|BLOCKER> <lockp> <cvt|held mode> <res name> <pid|did|txn_id> <node> The second to last field (<pid|did|txn_id>) could be a pid or the txn id depending on if we have an XID based deadlock search flag. However, as I already said. The mentioned txn id is not the transaction id that could be found in a Log Miner output. :-( -- Dusan Bolek
From: Dusan Bolek on 9 Nov 2005 04:47 It is getting more and more strange. We encountered today a bunch of problems that looks like a normal deadlock caused by application behaviour (lot of users deadlocking each other). In this case as you can see the mode is just same (5 on both ends) as with the previously mentioned deadlocks. The only difference is that these are occurying between instances. The strange is that these ones were accompanied with the SQL that caused the problem. So I'm not sure if in our case your statement "If the deadlock is on mode 5 enqueues at both ends, it is most likely to be the foreign key locking issue" is correct. See below: *** 2005-11-09 08:16:10.087 user session for deadlock lock 70000016a0b29b8 pid=825 serial=32833 audsid=14358159 user: 425/USER O/S info: user: wasadmin, term: , ospid: 1323120, machine: cn67b1 program: /was5/WebSphere/AppServer/java/bin/java(a)cn67b1 ( application name: /was5/WebSphere/AppServer/java/bin/java(a)cn67b1 (, hash value=0 Current SQL Statement: DELETE FROM SESSION_DATA WHERE SESSION_ID = :1 AND DATA_KEY = :2 user session for deadlock lock 70000016c0b07b0 pid=867 serial=37699 audsid=14358272 user: 425/USER O/S info: user: wasadmin, term: , ospid: 1323120, machine: cn67b1 program: /was5/WebSphere/AppServer/java/bin/java(a)cn67b1 ( application name: /was5/WebSphere/AppServer/java/bin/java(a)cn67b1 (, hash value=0 Current SQL Statement: DELETE FROM SESSION_DATA WHERE SESSION_ID = :1 AND DATA_KEY = :2 Global Wait-For-Graph(WFG) at ddTS[0.eff6] : BLOCKED 70000016a0b29b8 5 [0x20a0008][0x1cb52],[TX] [66361,527468] 0 BLOCKER 70000016f469718 5 [0x20a0008][0x1cb52],[TX] [131371,47259] 1 BLOCKED 70000016f469718 5 [0x20a0008][0x1cb52],[TX] [131371,47259] 1 BLOCKER 70000016bc15980 5 [0x20a0008][0x1cb52],[TX] [131217,103403] 1 BLOCKED 70000016b47f828 5 [0xbc001d][0x6ed23],[TX] [131217,103403] 1 BLOCKER 70000016d0b11a0 5 [0xbc001d][0x6ed23],[TX] [131469,20450] 1 BLOCKED 70000016d0b11a0 5 [0xbc001d][0x6ed23],[TX] [131469,20450] 1 BLOCKER 70000016d0b8a18 5 [0xbc001d][0x6ed23],[TX] [131394,51017] 1 BLOCKED 70000016d0b8b98 5 [0x400005][0x6914],[TX] [131394,51017] 1 BLOCKER 70000016c0b0648 5 [0x400005][0x6914],[TX] [66403,574442] 0 BLOCKED 70000016c0b07b0 5 [0x3d0017][0x82a7],[TX] [66403,574442] 0 BLOCKER 70000016a0b2400 5 [0x3d0017][0x82a7],[TX] [66361,527468] 0 -- Dusan Bolek
From: Jonathan Lewis on 10 Nov 2005 04:54 "Dusan Bolek" <spambin(a)seznam.cz> wrote in message news:1131529679.533983.16060(a)z14g2000cwz.googlegroups.com... > It is getting more and more strange. We encountered today a bunch of > problems that looks like a normal deadlock caused by application > behaviour (lot of users deadlocking each other). In this case as you > can see the mode is just same (5 on both ends) as with the previously > mentioned deadlocks. The only difference is that these are occurying > between instances. The strange is that these ones were accompanied with > the SQL that caused the problem. So I'm not sure if in our case your > statement "If the deadlock is on mode 5 enqueues at both ends, it is > most likely to be the foreign key locking issue" is correct. > My error - my comment is only appropriate for TM enqueues in mode 5; not TX in mode 5. On the other hand, I've never seen a TX in mode 5 - I had thought that modes 4 and 6 were the only possibilities for TX. So I wonder if we are being misled by the Metalink note. > See below: > > > *** 2005-11-09 08:16:10.087 > user session for deadlock lock 70000016a0b29b8 > pid=825 serial=32833 audsid=14358159 user: 425/USER > O/S info: user: wasadmin, term: , ospid: 1323120, machine: cn67b1 > program: /was5/WebSphere/AppServer/java/bin/java(a)cn67b1 ( > application name: /was5/WebSphere/AppServer/java/bin/java(a)cn67b1 (, > hash value=0 > Current SQL Statement: > DELETE FROM SESSION_DATA WHERE SESSION_ID = :1 AND DATA_KEY = :2 > user session for deadlock lock 70000016c0b07b0 > pid=867 serial=37699 audsid=14358272 user: 425/USER > O/S info: user: wasadmin, term: , ospid: 1323120, machine: cn67b1 > program: /was5/WebSphere/AppServer/java/bin/java(a)cn67b1 ( > application name: /was5/WebSphere/AppServer/java/bin/java(a)cn67b1 (, > hash value=0 > Current SQL Statement: > DELETE FROM SESSION_DATA WHERE SESSION_ID = :1 AND DATA_KEY = :2 > Global Wait-For-Graph(WFG) at ddTS[0.eff6] : > BLOCKED 70000016a0b29b8 5 [0x20a0008][0x1cb52],[TX] [66361,527468] 0 > BLOCKER 70000016f469718 5 [0x20a0008][0x1cb52],[TX] [131371,47259] 1 > BLOCKED 70000016f469718 5 [0x20a0008][0x1cb52],[TX] [131371,47259] 1 > BLOCKER 70000016bc15980 5 [0x20a0008][0x1cb52],[TX] [131217,103403] 1 > BLOCKED 70000016b47f828 5 [0xbc001d][0x6ed23],[TX] [131217,103403] 1 > BLOCKER 70000016d0b11a0 5 [0xbc001d][0x6ed23],[TX] [131469,20450] 1 > BLOCKED 70000016d0b11a0 5 [0xbc001d][0x6ed23],[TX] [131469,20450] 1 > BLOCKER 70000016d0b8a18 5 [0xbc001d][0x6ed23],[TX] [131394,51017] 1 > BLOCKED 70000016d0b8b98 5 [0x400005][0x6914],[TX] [131394,51017] 1 > BLOCKER 70000016c0b0648 5 [0x400005][0x6914],[TX] [66403,574442] 0 > BLOCKED 70000016c0b07b0 5 [0x3d0017][0x82a7],[TX] [66403,574442] 0 > BLOCKER 70000016a0b2400 5 [0x3d0017][0x82a7],[TX] [66361,527468] 0 > > -- > Dusan Bolek > Two thoughts - application oriented only: Does this code come from a logoff trigger ? Is webapplication server configured to drop a number of connections if they have been idle for a few minutes. The code looks like an attempt to record a logoff in the database - but in RAC, you can use the same session_id from different nodes, so maybe this code is simply not RAC-aware and causes a genuine deadlock somehow. -- Regards Jonathan Lewis http://www.jlcomp.demon.co.uk/faq/ind_faq.html The Co-operative Oracle Users' FAQ http://www.jlcomp.demon.co.uk/cbo_book/ind_book.html Cost Based Oracle: Fundamentals http://www.jlcomp.demon.co.uk/appearances.html Public Appearances - schedule updated 4th Nov 2005
From: Jonathan Lewis on 10 Nov 2005 04:57
<yong321(a)yahoo.com> wrote in message news:1131135857.443704.31690(a)g47g2000cwa.googlegroups.com... > Dusan Bolek wrote: >> > Metalink Note:262226.1 offers some interpretation. Your process 131321 >> > on node 1 is waiting for a TX lock in mode 5 (the two hex numbers, >> > 0x2b90011 and 0x5f20, may be id1 and id2 in v$lock, respectively). >> > Process 131317 on the same node is holding it. >> > You're right. I did some testing and find that the two numbers, > [131321,1285], in your case, do not in any way denote a process > (Note:262226.1 says the first number is PID). Instead they correspond > to transaction_id0 and transaction_id1 of v$ges_blocking_enqueue, > respectively (or the same in v$dlm_locks). Documentation says they're > lower and upper 4 bytes of the transaction identifier where the lock > belongs to. I can't find more information about it. Perhaps for our > purpose, we can conceptually think of the combination of the two > numbers, i.e. a transaction identifier, as a process identifier. > > By the way, I do see the SQL involved in the global deadlock (tested in > 9.2.0.7.0 on Linux): > ... > *** 2005-11-04 13:38:33.199 > user session for deadlock lock 0x7553ab14 > ... > Current SQL Statement: > update test set a = :"SYS_B_0" where a = :"SYS_B_1" > Global Wait-For-Graph(WFG) at ddTS[0.28] : > BLOCKED 0x7553ab14 5 [0xf001d][0x8353],[TX] [2162689,7995] 0 > ... > > In any case, follow Jonathan's practical advice. > > Yong Huang > Given that the documentation and notes are wrong about the process id / transaction id - might the comment about the mode 5 lock also be wrong ? Could you see a transaction holding or requesting a TX mode 5 in the few seconds before the deadlock was reported ? -- Regards Jonathan Lewis http://www.jlcomp.demon.co.uk/faq/ind_faq.html The Co-operative Oracle Users' FAQ http://www.jlcomp.demon.co.uk/cbo_book/ind_book.html Cost Based Oracle: Fundamentals http://www.jlcomp.demon.co.uk/appearances.html Public Appearances - schedule updated 4th Nov 2005 |