某天，應用程式突然掛了，程式中報錯連不上資料庫。登入資料庫主機後，發現sqlplus也登入不了，登入時，sqlplus長時間沒有響應，檢查alertlog只是發現半小時前檢測到一個deadlock，沒有其他的報錯資訊。心想oracle檢測到deadlock能自動解鎖，因此一開始沒懷疑到是因為deadlock的原因，由於登入不上資料庫，為了儘快的回覆業務，停掉應用程式，殺掉ps -ef |grep LOCAL=N的程式後，再次能登入資料庫，重啟了資料庫，再次啟動應用，回覆正常。
追溯原因時，一開始是懷疑係統的核心引數設定不正確，導致主機資源耗盡，因此無法sqlplus登入。但是檢查了一遍主機的核心引數，發現均正常。主機的syslog同樣也沒發現異常。奇怪，為什麼會出現掛死的現象？請教了老網蟲白鱔後，才明白了某些版本的oracle檢查到deadlock後會觸發一個關於deadlock的bug，導致enqueue hash chain的parent latch被hold住，然後在做SYSTEM DUMP的時候可能產生LATCH死鎖，這個時候可能hang住，時間可能是在幾秒鐘，也有可能是幾小時。
……
ARC0: Evaluating archive log 3 thread 1 sequence 36918
ARC0: Beginning to archive log 3 thread 1 sequence 36918
Creating archive destination LOG_ARCHIVE_DEST_1: '/arch/arch_1_36918.arc'
Thu Jan 31 15:59:13 2008
ARC0: Completed archiving log 3 thread 1 sequence 36918
Thu Jan 31 16:05:30 2008
Thread 1 advanced to log sequence 36920
Current log# 1 seq# 36920 mem# 0: /dev/vg_ora1/rredo_256m_01
Current log# 1 seq# 36920 mem# 1: /dev/vg_ora2/rredo_256m_11
Current log# 1 seq# 36920 mem# 2: /dev/vg_ora3/rredo_256m_21
Thu Jan 31 16:05:30 2008
ARC1: Evaluating archive log 4 thread 1 sequence 36919
ARC1: Beginning to archive log 4 thread 1 sequence 36919
Creating archive destination LOG_ARCHIVE_DEST_1: '/arch/arch_1_36919.arc'
Thu Jan 31 16:05:32 2008
ORA-000060: Deadlock detected. More info in file /oracle/app/oracle/admin/sd168/udump/sd168_ora_14652.trc.---- 注意此處
Thu Jan 31 17:00:11 2008
ARC1: Completed archiving log 4 thread 1 sequence 36919
Thu Jan 31 17:00:14 2008
SMON: Parallel transaction recovery tried
Thu Jan 31 17:02:34 2008
Thread 1 advanced to log sequence 36921
Current log# 2 seq# 36921 mem# 0: /dev/vg_ora1/rredo_256m_02
Current log# 2 seq# 36921 mem# 1: /dev/vg_ora2/rredo_256m_12
Current log# 2 seq# 36921 mem# 2: /dev/vg_ora3/rredo_256m_22
Thu Jan 31 17:02:34 2008
ARC0: Evaluating archive log 1 thread 1 sequence 36920
ARC0: Beginning to archive log 1 thread 1 sequence 36920
Creating archive destination LOG_ARCHIVE_DEST_1: '/arch/arch_1_36920.arc'
ARC0: Completed archiving log 1 thread 1 sequence 36920
……
ARC0: Evaluating archive log 3 thread 1 sequence 36918
ARC0: Beginning to archive log 3 thread 1 sequence 36918
Creating archive destination LOG_ARCHIVE_DEST_1: '/arch/arch_1_36918.arc'
Thu Jan 31 15:59:13 2008
ARC0: Completed archiving log 3 thread 1 sequence 36918
Thu Jan 31 16:05:30 2008
Thread 1 advanced to log sequence 36920
Current log# 1 seq# 36920 mem# 0: /dev/vg_ora1/rredo_256m_01
Current log# 1 seq# 36920 mem# 1: /dev/vg_ora2/rredo_256m_11
Current log# 1 seq# 36920 mem# 2: /dev/vg_ora3/rredo_256m_21
Thu Jan 31 16:05:30 2008
ARC1: Evaluating archive log 4 thread 1 sequence 36919
ARC1: Beginning to archive log 4 thread 1 sequence 36919
Creating archive destination LOG_ARCHIVE_DEST_1: '/arch/arch_1_36919.arc'
Thu Jan 31 16:05:32 2008
ORA-000060: Deadlock detected. More info in file /oracle/app/oracle/admin/sd168/udump/sd168_ora_14652.trc.---- 注意此處
Thu Jan 31 17:00:11 2008
ARC1: Completed archiving log 4 thread 1 sequence 36919
Thu Jan 31 17:00:14 2008
SMON: Parallel transaction recovery tried
Thu Jan 31 17:02:34 2008
Thread 1 advanced to log sequence 36921
Current log# 2 seq# 36921 mem# 0: /dev/vg_ora1/rredo_256m_02
Current log# 2 seq# 36921 mem# 1: /dev/vg_ora2/rredo_256m_12
Current log# 2 seq# 36921 mem# 2: /dev/vg_ora3/rredo_256m_22
Thu Jan 31 17:02:34 2008
ARC0: Evaluating archive log 1 thread 1 sequence 36920
ARC0: Beginning to archive log 1 thread 1 sequence 36920
Creating archive destination LOG_ARCHIVE_DEST_1: '/arch/arch_1_36920.arc'
ARC0: Completed archiving log 1 thread 1 sequence 36920
……
進一步檢查這個deadlock的trace檔案：
/oracle/app/oracle/admin/sd168/udump/sd168_ora_14652.trc
Oracle9i Enterprise Edition Release 9.2.0.6.0 - 64bit Production
With the Partitioning, OLAP and Oracle Data Mining options
JServer Release 9.2.0.6.0 - Production
ORACLE_HOME = /oracle/app/oracle/product/9.2.0
System name: HP-UX
Node name: sd_db01
Release: B.11.11
Version: U
Machine: 9000/800
Instance name: sd168
Redo thread mounted by this instance: 1
Oracle process number: 590
Unix process pid: 14652, image: oracle@sd_db01 (TNS V1-V3)
*** 2008-01-31 16:05:32.480
*** SESSION ID:(465.37272) 2008-01-31 16:05:32.403
DEADLOCK DETECTED
Current SQL statement for this session:
delete eips_corporation corp where corp.corpid=:1
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
TM-0000872c-00000000 590 465 SX SSX 581 281 SX SSX -------注意此處
TM-0000872c-00000000 581 281 SX SSX 590 465 SX SSX
session 465: DID 0001-024E-0000003F session 281: DID 0001-0245-0000002E
session 281: DID 0001-0245-0000002E session 465: DID 0001-024E-0000003F
Rows waited on:
Session 281: obj - rowid = 00008762 - AAAIdiACGAAAAAAAAA
(dictionary objn - 34658, file - 134, block - 0, slot - 0)
Session 465: obj - rowid = 00008762 - AAAIdiACGAAAAAAAAA
(dictionary objn - 34658, file - 134, block - 0, slot - 0)
Information on the OTHER waiting sessions:
Session 281:
pid=581 serial=53477 audsid=7366710 user: 54/EICP
O/S info: user: eicp, term: unknown, ospid: , machine: sd-oam01
program: JDBC Thin Client
application name: JDBC Thin Client, hash value=0
Current SQL Statement:
delete eips_corporation corp where corp.corpid=:1
End of information on OTHER waiting sessions.
===================================================
PROCESS STATE
-------------
Process global information:
process: c0000001991a1720, call: c0000001a57bcfd8, xact: c00000019bfbc5b0, curses: c0000001993bfd88, usrses: c0000001993bfd88
----------------------------------------
SO: c0000001991a1720, type: 2, owner: 0000000000000000, flag: INIT/-/-/0x00
(process) Oracle pid=590, calls cur/top: c0000001a57bcfd8/c0000001a57bcfd8, flag: (0) -
int error: 0, call error: 0, sess error: 0, txn error 0
(post info) last post received: 197 0 4
last post received-location: kslpsr
last process to post me: c0000001990e5be0 1 6
last post sent: 0 0 16
last post sent-location: ksasnd
last process posted by me: c0000001990e5be0 1 6
(latch info) wait_event=0 bits=10
holding c0000001c1a4d458 Parent+children enqueue hash chains level=4 -------注意此處
Location from where latch is held: ksqcmi: kslgpl:
Context saved from call: 0
state=busy
recovery area:
Dump of memory from 0xC0000001990E4628 to 0xC0000001990E4638
……
Oracle9i Enterprise Edition Release 9.2.0.6.0 - 64bit Production
With the Partitioning, OLAP and Oracle Data Mining options
JServer Release 9.2.0.6.0 - Production
ORACLE_HOME = /oracle/app/oracle/product/9.2.0
System name: HP-UX
Node name: sd_db01
Release: B.11.11
Version: U
Machine: 9000/800
Instance name: sd168
Redo thread mounted by this instance: 1
Oracle process number: 590
Unix process pid: 14652, image: oracle@sd_db01 (TNS V1-V3)
*** 2008-01-31 16:05:32.480
*** SESSION ID:(465.37272) 2008-01-31 16:05:32.403
DEADLOCK DETECTED
Current SQL statement for this session:
delete eips_corporation corp where corp.corpid=:1
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
TM-0000872c-00000000 590 465 SX SSX 581 281 SX SSX -------注意此處
TM-0000872c-00000000 581 281 SX SSX 590 465 SX SSX
session 465: DID 0001-024E-0000003F session 281: DID 0001-0245-0000002E
session 281: DID 0001-0245-0000002E session 465: DID 0001-024E-0000003F
Rows waited on:
Session 281: obj - rowid = 00008762 - AAAIdiACGAAAAAAAAA
(dictionary objn - 34658, file - 134, block - 0, slot - 0)
Session 465: obj - rowid = 00008762 - AAAIdiACGAAAAAAAAA
(dictionary objn - 34658, file - 134, block - 0, slot - 0)
Information on the OTHER waiting sessions:
Session 281:
pid=581 serial=53477 audsid=7366710 user: 54/EICP
O/S info: user: eicp, term: unknown, ospid: , machine: sd-oam01
program: JDBC Thin Client
application name: JDBC Thin Client, hash value=0
Current SQL Statement:
delete eips_corporation corp where corp.corpid=:1
End of information on OTHER waiting sessions.
===================================================
PROCESS STATE
-------------
Process global information:
process: c0000001991a1720, call: c0000001a57bcfd8, xact: c00000019bfbc5b0, curses: c0000001993bfd88, usrses: c0000001993bfd88
----------------------------------------
SO: c0000001991a1720, type: 2, owner: 0000000000000000, flag: INIT/-/-/0x00
(process) Oracle pid=590, calls cur/top: c0000001a57bcfd8/c0000001a57bcfd8, flag: (0) -
int error: 0, call error: 0, sess error: 0, txn error 0
(post info) last post received: 197 0 4
last post received-location: kslpsr
last process to post me: c0000001990e5be0 1 6
last post sent: 0 0 16
last post sent-location: ksasnd
last process posted by me: c0000001990e5be0 1 6
(latch info) wait_event=0 bits=10
holding c0000001c1a4d458 Parent+children enqueue hash chains level=4 -------注意此處
Location from where latch is held: ksqcmi: kslgpl:
Context saved from call: 0
state=busy
recovery area:
Dump of memory from 0xC0000001990E4628 to 0xC0000001990E4638
……
檢查addr為c0000001c1a4d458的latch：
SQL> select name from v$latch where addr=upper('c0000001c1a4d458');
NAME
----------------------------------------------------------------
enqueue hash chains
NAME
----------------------------------------------------------------
enqueue hash chains
確實我們看到了enqueue hash chain。enqueue hash chain是用於保護每一個library cache中的hash bucket。
（這裡借用一下eygle的圖說明一下library cache的結構）
由於parent latch被HOLD了，所有對資料庫library cache加鎖的操作都無法進行，而sqlplus登入的時候要申請AUDSES$的SEQUENCE，因此sqlplus無法登入，同理所有的應用程式也無法登入——應用程式掛死。
在metalink上也確認了這個bug：2530125
可是，在第二天下午，再次出現的由於deadlock導致資料庫掛死的問題，檢查alertlog發現在很早之前已經有deadlock的現象，為何系統會頻繁的出現deadlock？
根據deadlock的trace檔案，根據deadlock graph的wait的模式是SSX，這就很有可能是外來鍵沒加索引造成。檢查相關語句中的外來鍵，靠！確實是外來鍵沒加索引。
對外來鍵增加索引後，系統正常執行一週，不再發生死鎖，也不再發生掛死現象。至此問題解決。回顧問題：由於外來鍵沒加索引–引起死鎖–觸發bug2530125–enqueue hash latch–無法登入–程式掛死。