Author: rainnyzhong

Date: 2010-01-08

不得不记录一下。这个问题花了我一天的时间来追踪。

最先是怀疑外键字段是否没有建索引。然后我给相关的外键字段都建上索引，死锁依旧。

后来怀疑是ORACLE的BUG，因为ORACLE确实有一个BUG：2530125，某些版本的oracle检查到deadlock后会触发一个关于deadlock的bug。

我将整个SCHEMA导出到另外一个DB(64位平台)，发现死锁依旧。所以暂时去除了是ORACLE BUG的嫌疑.

再后来怀疑存储过程或JAVA中是否有生成动态SQL(ad-hoc SQL),检查代码，发现确实有动态SQL。将JAVA和PROCEDURE中的动态SQL去掉，死锁依旧。

靠！到这一步，心里郁闷的不得了。

再次仔细检查死锁的trace文件，发现有一个LATCH：

Parent+children enqueue hash chains level=4

SELECT * FROM V$LATCH L WHERE L.ADDR=upper('20004fc4')；

--

1 20004FC4 19 4 enqueue hash chains 1456202064 584423 76 0 14395 1 0 0 76 0 0 0 0 0 0 0 0 0 0 0 0

发现确实存在这么一个latch：enqueue hash chain.我重启DB，发现这个latch依然存在，并且发现v$latch这个视图的记录在DB重启之前和重启之后总数量是一样的(382行)。于是，我就再次写SQL故意重现一把死锁，再检视模拟出来的死锁的trace文件，发现里面也有这个latch,可见，只要是死锁，这个latch就会出现在trace文件中，没有什么特别的地方。

思索再思索，最后发现唯一特别的地方是死锁图(deadlock graph)：

Deadlock graph:

---------Blocker(s)-------- ---------Waiter(s)---------

Resource Name process session holds waits process session holds waits

TX-0009000d-0000207b 38 721 X 38 721 X

session 721: DID 0001-0026-00001DE8 session 721: DID 0001-0026-00001DE8

Rows waited on:

Session 721: obj - rowid = 0000EAF8 - AAAPzHAAGAAAVGzAAA

(dictionary objn - 60152, file - 6, block - 86451, slot - 0)

正常的死锁图，一般是有两行，而我的只有一行，且是同一SESSION（如上图），而正常的死锁图应该是像下面这样：

DEADLOCK DETECTED

[Transaction Deadlock]

Current SQL statement for this session:

DELETE FROM pm_user_temp WHERE rownumber=4

The following deadlock is not an ORACLE error. It is a

deadlock due to user error in the design of an application

or from issuing incorrect ad-hoc SQL. The following

information may aid in determining the deadlock:

Deadlock graph:

---------Blocker(s)-------- ---------Waiter(s)---------

Resource Name process session holds waits process session holds waits

TX-00070015-00001881 41 772 X 94 670 X

TX-0001000b-00001822 94 670 X 41 772 X

session 772: DID 0001-0029-00000008 session 670: DID 0001-005E-00000004

session 670: DID 0001-005E-00000004 session 772: DID 0001-0029-00000008

Rows waited on:

Session 670: obj - rowid = 0000EAF8 - AAAPzHAAGAAAVGwAAA

(dictionary objn - 60152, file - 6, block - 86448, slot - 0)

Session 772: obj - rowid = 0000EAF8 - AAAPzHAAGAAAVGwAAC

(dictionary objn - 60152, file - 6, block - 86448, slot - 2)

Information on the OTHER waiting sessions:

Session 670:

pid=94 serial=464 audsid=35675 user: 69/XPC92_IMPORT_JEFF

O/S info: user: rainnyzhong, term: RAINNYZHONG-ECV, ospid: 3008:1404, machine: MSHOMERAINNYZHONG-ECV

program: plsqldev.exe

application name: PL/SQL Developer, hash value=1190136663

action name: SQL Window - New, hash value=3399691616

Current SQL Statement:

DELETE FROM pm_user_temp WHERE rownumber=2

End of information on OTHER waiting sessions.

上面是我模拟出来的死锁产生的trace文件中包含的死锁图。在一个正常的死锁图中，一般是至少是有2个资源被锁住，而本例的死锁图中，只有一个资源被锁住，且是被同一会话锁住。这有点特别。

无奈之下，再次回退最近所有新修改的PROCEDURE和JAVA代码，死锁依旧。

这个PROCDUER已经运行一段时间了，QA也测了一段时间，一直没有报这种死锁的问题，那么，为什么现在会报出来呢？苦思，再苦思，最后，开发人员突然想起来说，他用的是MOCK，而不是JBOSS。我们马上将代码放到JBOSS运行，死锁不再抛出，到此，困了我一天的死锁问题终于找到原因。经过咨询开发人员，原来MOCK是我们的AD TEADM研发出来的一个东东，有点类似模拟JBOSS，主要是用于开发人员的内部测试，在一般的测试中，开发人员只要用MOCK，而不需用JBOSS就可以调试代码。但我们做的MOCK没办法真正模拟出JBOSS的事务管理机制，没办法实现嵌套事务，自治事务等。检视ORACLE 的PROCEDURE，确实存在自治事务，所以，用MOCK一运行，就抛出来莫名其妙的死锁，产生的死锁图也是非常特别。靠！要不是开发人员自己说出来，我调2天估计也查不出死锁的原因。

下面为完整的死锁TRACE文件

PARSING IN CURSOR #27 len=153 dep=1 uid=69 oct=6 lid=69 tim=1233331432659515 hv=3592496474 ad='46e29a38'

UPDATE PM_USER_TEMP T SET T.DEFAULTROLENAME = 'core.pm/label.companyAdministrator' WHERE T.DEFAULTROLENAME = :B3 AND T.USERID = :B2 AND T.FILENAME = :B1

END OF STMT

PARSE #27:c=0,e=282,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=1233331432659507

DEADLOCK DETECTED

[Transaction Deadlock]

Current SQL statement for this session:

UPDATE PM_USER_TEMP T SET T.DEFAULTROLENAME = 'core.pm/label.companyAdministrator' WHERE T.DEFAULTROLENAME = :B3 AND T.USERID = :B2 AND T.FILENAME = :B1

----- PL/SQL Call Stack -----

object line object

handle number name

0x3d26c364 470 procedure XPC92_IMPORT_JEFF.AIT_LOADTEMPDATA

0x3d26c51c 1 anonymous block

The following deadlock is not an ORACLE error. It is a

deadlock due to user error in the design of an application

or from issuing incorrect ad-hoc SQL. The following

information may aid in determining the deadlock:

Deadlock graph:

---------Blocker(s)-------- ---------Waiter(s)---------

Resource Name process session holds waits process session holds waits

TX-0009000d-0000207b 38 721 X 38 721 X

session 721: DID 0001-0026-00001DE8 session 721: DID 0001-0026-00001DE8

Rows waited on:

Session 721: obj - rowid = 0000EAF8 - AAAPzHAAGAAAVGzAAA

(dictionary objn - 60152, file - 6, block - 86451, slot - 0)

Information on the OTHER waiting sessions:

End of information on OTHER waiting sessions.

===================================================

PROCESS STATE

-------------

Process global information:

process: 0x4cf5d02c, call: 0x496db50c, xact: 0x4b1bbd4c, curses: 0x4cbcf25c, usrses: 0x4cbcf25c

----------------------------------------

SO: 0x4cf5d02c, type: 2, owner: (nil), flag: INIT/-/-/0x00

(process) Oracle pid=38, calls cur/top: 0x496db50c/0x4970dcdc, flag: (0) -

int error: 0, call error: 0, sess error: 0, txn error 0

(post info) last post received: 108 0 4

last post received-location: kslpsr

last process to post me: 4cf519ac 1 6

last post sent: 0 0 24

last post sent-location: ksasnd

last process posted by me: 4cf519ac 1 6

(latch info) wait_event=0 bits=10

holding (efd=19) 20004fc4 Parent+children enqueue hash chains level=4

Location from where latch is held: ksqcmi: kslgpl:

Context saved from call: 0

state=busy, wlstate=free

recovery area:

…..此外省略n行

[@more@]

ITPub博客

一个ORACLE死锁问题的追踪

最新文章