結論

1,oracle應用死鎖會產生trace file，並且會在告警日誌記錄相關檔案的目錄
2,trace file大體包括幾部分內容
3,第一部分內容為：表明死鎖是什麼型別的死鎖
資訊如下：
DEADLOCK DETECTED ( ORA-00060 )

[Transaction Deadlock]

The following deadlock is not an ORACLE error. It is a --標明死鎖是由應用本面設計不合理或者SQL原因引發，而本ORACLE本身的原因導致
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:

4，第二部分內容為：死鎖的阻塞者及等待者詳細資訊

Deadlock graph:

競爭的資源 ----可見分為阻塞者以及等待者
---------Blocker(s)-------- ---------Waiter(s)---------
Resource Name process session holds waits process session holds waits
TX-00b40017-00002e45 184 241 X 185 261 X
TX-00c2001d-00002c68 185 261 X 184 241 X

4.1,關於上述4的競爭資源含義：競爭的資源第2部分表明xidusn,xidslot,xidsqn,對應於v$transaction，具體分析見下測試細節

4.2,關於阻塞者及等待者的含義：見文識義，不再複述

5，第三部分內容為：與死鎖相關的表記錄資訊

Rows waited on:
Session 241: obj - rowid = 000125EF - AAASXvAAEAAAYJPAAA --相關的死鎖會話，表記錄對應的ROWID
(dictionary objn - 75247, file - 4, block - 98895, slot - 0) --死鎖的物件，所屬檔案及塊號，以及槽編號
Session 261: obj - rowid = 000125EF - AAASXvAAEAAAYJPAAB
(dictionary objn - 75247, file - 4, block - 98895, slot - 1)

6，死鎖所屬程式的資訊
包括了程式資訊，所屬會話的資訊，會話執行SQL以及等待事件和歷史等待事件列表相關資訊

Information for THIS session:

----- Current SQL Statement for this session (sql_id=b3tmrc0st5pyb) -----
update t_lock set a=11 where a=1
===================================================
PROCESS STATE
-------------
Process global information:
process: 0xdd6589c0, call: 0xd27aead8, xact: 0xd9898658, curses: 0xdc90b030, usrses: 0xdc90b030
----------------------------------------
SO: 0xdd6589c0, type: 2, owner: (nil), flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0xdd6589c0, name=process, file=ksu.h LINE:11459, pg=0
(process) Oracle pid:184, ser:2, calls cur/top: 0xd27aead8/0xd27aead8
flags : (0x0) -
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 252
具體資訊請參見如下測試細節

測試

---oracle version
SQL> select * from v$version where rownum=1;

BANNER
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production

---session 241
SQL> select sid from v$mystat where rownum=1;

SID
----------
241

SQL> select pid,spid,addr from v$process where addr=(select paddr from v$session where sid=(select sid from v$mystat where rownum=1));

PID SPID ADDR
---------- ------------------------------------------------ ----------------
184 15936 00000000DD6589C0

SQL> create table t_lock(a int,b int);

Table created.

SQL> insert into t_lock select level,level from dual connect by level<=2;

2 rows created.

SQL> commit;

Commit complete.

SQL> select * from t_lock;

A B
---------- ----------
1 1
2 2

SQL> update t_lock set a=22 where a=2;

1 row updated.

----session 261
SQL> select sid from v$mystat where rownum=1;

SID
----------
261

SQL> update t_lock set a=11 where a=1;

1 row updated.

SQL> select pid,spid,addr from v$process where addr=(select paddr from v$session where sid=(select sid from v$mystat where rownum=1));

PID SPID ADDR
---------- ------------------------------------------------ ----------------
185 15937 00000000DD659A00

---session 241及261分別執行如下
SQL> update t_lock set a=11 where a=1;
update t_lock set a=11 where a=1
*
ERROR at line 1:
ORA-00060: deadlock detected while waiting for resource

---session 261
SQL> update t_lock set a=22 where a=2;

檢視告警日誌，可見出現死鎖會記錄在告警日誌
[root@seconary ~]# su - oracle
[oracle@seconary ~]$ cd /oracle/diag/rdbms/guowang/guowang/trace/
[oracle@seconary trace]$ tail -f alert_guowang.log

Sun Nov 08 19:06:04 2015
ORA-00060: Deadlock detected. More info in file /oracle/diag/rdbms/guowang/guowang/trace/guowang_ora_15936.trc.

我們分析下死鎖的TRACE FILE,獲取有價值的內容，直接在原始檔直行分析，便於交插參考

*** 2015-11-08 19:06:01.260
DEADLOCK DETECTED ( ORA-00060 )

[Transaction Deadlock]

The following deadlock is not an ORACLE error. It is a --標明死鎖是由應用本面設計不合理或者SQL原因引發，而本ORACLE本身的原因導致
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-00b40017-00002e45 184 241 X 185 261 X
TX-00c2001d-00002c68 185 261 X 184 241 X

由上可見，有2條記錄，第一條記錄表明261會話請求排它X鎖，卻發現當被241會話以X排它模式持有，所以只能等待
第二條記錄同理，但剛好相反

小結下：
上述包括：
競爭的資源：它有3部分構成，第一部分很簡單，表明鎖的型別，第2和第3部分，請繼續看我下面的分析
阻塞者資訊：程式，會話，持鎖模式，等待模式
等待者資訊：程式，會話，持鎖模式，等待模式

先看下上述競爭的資源構成
SQL> select type,name,id1_tag,id2_tag,is_user,description from v$lock_type where lower(type) like '%tx%';

TYPE NAME ID1_TAG ID2_TAG IS_USER DESCRIPTION
--------------- ------------------------- -------------------- -------------------- ---------- --------------------------------------------------
TX Transaction usn<<16 | slot sequence YES Lock held by a transaction to allow other transact
ions to wait for it

SQL> select saddr,sid from v$session where sid in (241,261);

SADDR SID
---------------- ----------
00000000DC90B030 241
00000000DC8D0F70 261

SQL> select xidusn,xidslot,xidsqn,ubafil,ubablk,ubasqn,ubarec from v$transaction where ses_addr in ('00000000DC90B030','00000000DC8D0F70');

XIDUSN XIDSLOT XIDSQN UBAFIL UBABLK UBASQN UBAREC
---------- ---------- ---------- ---------- ---------- ---------- ----------
194 29 11368 7 755 2670 23
180 23 11845 7 531 2810 37

SQL> select to_char(194,'xxxxxxx') xidusn,to_char(29,'xxxxxxx') xidslot,to_char(11368,'xxxxxxx') xidsqn from dual;

XIDUSN XIDSLOT XIDSQN
---------------- ---------------- ----------------
c2 1d 2c68

可見競爭的資源第2部分表明xidusn,xidslot,xidsqn,對應於v$transaction

再看下did,參考前文：http://blog.itpub.net/9240380/viewspace-1819341/

session 241: DID 0001-00B8-00000003 session 261: DID 0001-00B9-00000001
session 261: DID 0001-00B9-00000001 session 241: DID 0001-00B8-00000003

可見死鎖DID在2個會話就是交插的，很易理解，因為是死鎖嗎

繼續看，會顯示與死鎖相關的表記錄資訊

Rows waited on:
Session 241: obj - rowid = 000125EF - AAASXvAAEAAAYJPAAA --相關的死鎖會話，表記錄對應的ROWID
(dictionary objn - 75247, file - 4, block - 98895, slot - 0) --死鎖的物件，所屬檔案及塊號，以及槽編號
Session 261: obj - rowid = 000125EF - AAASXvAAEAAAYJPAAB
(dictionary objn - 75247, file - 4, block - 98895, slot - 1)

SQL> select object_id,object_name from dba_objects where object_id=75247;

OBJECT_ID OBJECT_NAME
---------- ------------------------------
75247 T_LOCK

SQL> select a,b,rowid from scott.t_lock;

A B ROWID
---------- ---------- ------------------
1 1 AAASXvAAEAAAYJPAAA
2 2 AAASXvAAEAAAYJPAAB

--透過死鎖記錄的ROWID可以定位到表對應的記錄
SQL> select a,b,rowid from scott.t_lock where rowid in ('AAASXvAAEAAAYJPAAA','AAASXvAAEAAAYJPAAB');

A B ROWID
---------- ---------- ------------------
1 1 AAASXvAAEAAAYJPAAA
2 2 AAASXvAAEAAAYJPAAB

再看看上述的slot含義是什麼呢？
SQL> select DBMS_ROWID.ROWID_RELATIVE_FNO(ROWID) file_no,DBMS_ROWID.ROWID_BLOCK_NUMBER(ROWID) block_no,dbms_rowid.rowid_row_number(rowid) record_no from scott.t_lock;

FILE_NO BLOCK_NO RECORD_NO
---------- ---------- ----------
4 98895 0
4 98895 1

結合BLOCK DUMP可知上述的slot代表record_no記錄的標號
Block header dump: 0x0101824f
Object id on Block? Y
seg/obj: 0x125ef csc: 0x00.4b9039a itc: 2 flg: E typ: 1 - DATA
brn: 0 bdba: 0x1018248 ver: 0x01 opc: 0
inc: 0 exflg: 0

Itl Xid Uba Flag Lck Scn/Fsc
0x01 0x00b4.017.00002e45 0x01c00213.0afa.25 ---- 1 fsc 0x0000.00000000
0x02 0x00c2.01d.00002c68 0x01c002f3.0a6e.17 ---- 1 fsc 0x0000.00000000

下面資訊會顯示導致死鎖會話正在執行的SQL
----- Information for the OTHER waiting sessions -----
Session 261:
sid: 261 ser: 9 audsid: 31722060 user: 84/SCOTT flags: 0x45
pid: 185 O/S info: user: oracle, term: UNKNOWN, ospid: 15937
image: oracle@seconary (TNS V1-V3)
client details:
O/S info: user: oracle, term: pts/4, ospid: 15933
machine: seconary program: sqlplus@seconary (TNS V1-V3)
application name: SQL*Plus, hash value=3669949024
current SQL:
update t_lock set a=22 where a=2 --正在執行的SQL

----- End of information for the OTHER waiting sessions -----

死鎖所屬程式的資訊
包括了程式資訊，所屬會話的資訊，會話執行SQL以及等待事件和歷史等待事件列表相關資訊

Information for THIS session:

----- Current SQL Statement for this session (sql_id=b3tmrc0st5pyb) -----
update t_lock set a=11 where a=1
===================================================
PROCESS STATE
-------------
Process global information:
process: 0xdd6589c0, call: 0xd27aead8, xact: 0xd9898658, curses: 0xdc90b030, usrses: 0xdc90b030
----------------------------------------
SO: 0xdd6589c0, type: 2, owner: (nil), flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0xdd6589c0, name=process, file=ksu.h LINE:11459, pg=0
(process) Oracle pid:184, ser:2, calls cur/top: 0xd27aead8/0xd27aead8
flags : (0x0) -
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 252
last post received-location: kgsk2.h LINE:638 ID:kgskrunnextint: posting new vt to run
last process to post me: dd5ba2c0 2 2
last post sent: 0 0 253
last post sent-location: kgsk2.h LINE:641 ID:kgskchk: posting new vt to run
last process posted by me: dd5be3c0 6 0
(latch info) wait_event=0 bits=0
Process Group: DEFAULT, pseudo proc: 0xdd9a34d0
O/S info: user: oracle, term: UNKNOWN, ospid: 15936
OSD pid info: Unix process pid: 15936, image: oracle@seconary (TNS V1-V3)
Dump of memory from 0x00000000DD536240 to 0x00000000DD536448
0DD536240 00000000 00000000 00000000 00000000 [................]
Repeat 31 times
0DD536440 00000000 00000000 [........]
(FOB) flags=2050 fib=0xd8f365d0 incno=0 pending i/o cnt=0
fname=/oracle/oradata/guowang/tbs_undo_nb.dbf
fno=7 lblksz=8192 fsiz=10656
----------------------------------------
SO: 0xdb964af8, type: 13, owner: 0xdd6589c0, flag: INIT/-/-/0x00 if: 0x1 c: 0x1
proc=0xdd6589c0, name=channel handle, file=ksr2.h LINE:347, pg=0
(broadcast handle) 0xdb964af8 flag: (1) PUBLISHER,
owner: 0xdd6589c0 - ospid: 15936
event: 2, last message event: 0,
last message waited event: 0,
next message: (nil)(0), messages published: 1
channel: (0xdb9b20b0) RBR channel [name: 29]
scope: 7, event: 186, last mesage event: 186,
publishers/subscribers: 2/1,
messages published: 177
heuristic msg queue length: 0
----------------------------------------
SO: 0xdb964958, type: 13, owner: 0xdd6589c0, flag: INIT/-/-/0x00 if: 0x1 c: 0x1
proc=0xdd6589c0, name=channel handle, file=ksr2.h LINE:347, pg=0
(broadcast handle) 0xdb964958 flag: (1) PUBLISHER,
owner: 0xdd6589c0 - ospid: 15936
event: 2, last message event: 0,
last message waited event: 0,
next message: (nil)(0), messages published: 1
channel: (0xdb9b2208) obj broadcast channel [name: 30]
scope: 7, event: 121, last mesage event: 121,
publishers/subscribers: 1/1,
messages published: 118
heuristic msg queue length: 0
(FOB) flags=2050 fib=0xd8f353a0 incno=0 pending i/o cnt=0
fname=/oracle/oradata/guowang/users01.dbf
fno=4 lblksz=8192 fsiz=108800
(FOB) flags=2050 fib=0xd8f377e8 incno=0 pending i/o cnt=0
fname=/oracle/oradata/guowang/temp02.dbf
fno=202 lblksz=8192 fsiz=131072
(FOB) flags=2050 fib=0xd8f371e8 incno=0 pending i/o cnt=0
fname=/oracle/oradata/guowang/temp01.dbf
fno=201 lblksz=8192 fsiz=2560
(FOB) flags=2050 fib=0xd8f34788 incno=0 pending i/o cnt=0
fname=/oracle/oradata/guowang/sysaux01.dbf
fno=2 lblksz=8192 fsiz=198400
(FOB) flags=2050 fib=0xd8f34188 incno=0 pending i/o cnt=0
fname=/oracle/oradata/guowang/system01.dbf
fno=1 lblksz=8192 fsiz=145920
----------------------------------------
SO: 0xdc90b030, type: 4, owner: 0xdd6589c0, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
proc=0xdd6589c0, name=session, file=ksu.h LINE:11467, pg=0
(session) sid: 241 ser: 10 trans: 0xd9898658, creator: 0xdd6589c0
flags: (0x45) USR/- flags_idl: (0x1) BSY/-/-/-/-/-
flags2: (0x40008) -/-
DID: , short-term DID:
txn branch: (nil)
oct: 6, prv: 0, sql: 0xce920f68, psql: 0xcedb6180, user: 84/SCOTT
ksuxds FALSE at location: 0
service name: SYS$USERS
client details:
O/S info: user: oracle, term: pts/5, ospid: 15935
machine: seconary program: sqlplus@seconary (TNS V1-V3)
application name: SQL*Plus, hash value=3669949024
Current Wait Stack:
0: waiting for 'enq: TX - row lock contention'
name|mode=0x54580006, usn<<16 | slot=0xc2001d, sequence=0x2c68
wait_id=257 seq_num=258 snap_id=1
wait times: snap=19.179006 sec, exc=19.179006 sec, total=19.179006 sec
wait times: max=infinite, heur=19.179006 sec
wait counts: calls=6 os=6
in_wait=1 iflags=0x15a0
There are 1 sessions blocked by this session.
Dumping one waiter:
inst: 1, sid: 11, ser: 1
wait event: 'latch: enqueue hash chains'
p1: 'address'=0xdb69fea0
p2: 'number'=0x1c
p3: 'tries'=0x0
row_wait_obj#: 4294967295, block#: 0, row#: 0, file# 0
min_blocked_time: 0 secs, waiter_cache_ver: 1014

oracle deadlock死鎖trace file分析之一

結論

測試

相關文章