SystemState分析案例（三）
這個TRC來源於網上，TRC可以在這裡下載 http://www.oraclefans.cn/forum/showtopic.jsp?rootid=23872
ass109.awk格式化Systemstats後發現，主要會話在等待cursor: pin S wait on X。
搜尋 [ waiting for ‘cursor: pin S wait on X’ ]，大量會話等待的資源都相同
為驗證，接著搜尋[ idn=.*value= ]。根據資訊確定其等待的資源為943724ff，阻塞者為SID 3137，其以Exclusive持有該Mutex
搜尋 [ Mutex.*943724ff ]，發現大量會話在其上請求Shared鎖，而Process 134（SID 3137）在上面持有Exclusive
KGX Atomic Operation Log 0x4aebe8aa0
Mutex 0x508397d00(3137, 0) idn 943724ff oper EXCL
Cursor Pin uid 3137 efd 0 whr 1 slp 0
pr=3 pso=0x4c3043b18 flg=0
pcs=0x508397d00 nxt=(nil) flg=34 cld=0 hd=0x3b8d004f8 par=0x5083980f0
ct=0 hsh=0 unp=(nil) unn=0 hvl=83983c8 nhv=1 ses=0x55bc76f08
hep=0x508397d80 flg=80 ld=1 b=0x5083972d0 ptr=0x40d96e2d0 fex=0x40d96d5e0
檢查Process 134，發現其在等待 DFS lock handle
PROCESS 134:
----------------------------------------
SO: 0x55a1646f8, type: 2, owner: (nil), flag: INIT/-/-/0x00
(process) Oracle pid=134, calls cur/top: 0x52ac62ef8/0x5053a18c8, flag: (0) -
int error: 0, call error: 0, sess error: 0, txn error 0
(post info) last post received: 0 0 172
last post received-location: kqrbpr: post after requeueing
last process to post me: 55a148c38 1 6
last post sent: 0 0 90
last post sent-location: KJCS Post snd proxy to flush msg
last process posted by me: 55a144cf8 1 6
(latch info) wait_event=0 bits=0
Process Group: DEFAULT, pseudo proc: 0x55b43ce00
O/S info: user: oracle, term: UNKNOWN, ospid: 19054
OSD pid info: Unix process pid: 19054, image: oracle@nc02
*** 2010-09-27 10:05:47.633
Short stack dump:
ksdxfstk()+32
----------------------------------------
SO: 0x55bc76f08, type: 4, owner: 0x55a1646f8, flag: INIT/-/-/0x00
(session) sid: 3137 trans: (nil), creator: 0x55a1646f8, flag: (41) USR/- BSY/-/-/-/-/-
DID: 0002-0086-00000049, short-term DID: 0002-0086-0000004A
txn branch: (nil)
oct: 3, prv: 0, sql: 0x49b8c2830, psql: 0x4b5d062a0, user: 33/BBG519
service name: ncrac
O/S info: user: Administrator, term: , ospid: 1234, machine: bbgapp01
program:
waiting for 'DFS lock handle' blocking sess=0x(nil) seq=2106 wait_time=0 seconds since wait started=3021
type|mode=43490005, id1=1e, id2=5
Dumping Session Wait History
for 'DFS lock handle' count=1 wait_time=1944973
type|mode=43490005, id1=1e, id2=5
for 'DFS lock handle' count=1 wait_time=489249
type|mode=43490005, id1=1e, id2=5
for 'DFS lock handle' count=1 wait_time=489252
type|mode=43490005, id1=1e, id2=5
for 'DFS lock handle' count=1 wait_time=489234
type|mode=43490005, id1=1e, id2=5
for 'DFS lock handle' count=1 wait_time=489263
type|mode=43490005, id1=1e, id2=5
for 'DFS lock handle' count=1 wait_time=489249
type|mode=43490005, id1=1e, id2=5
for 'DFS lock handle' count=1 wait_time=489235
type|mode=43490005, id1=1e, id2=5
for 'DFS lock handle' count=1 wait_time=489252
type|mode=43490005, id1=1e, id2=5
for 'DFS lock handle' count=1 wait_time=489259
type|mode=43490005, id1=1e, id2=5
for 'DFS lock handle' count=1 wait_time=489253
type|mode=43490005, id1=1e, id2=5
temporary object counter: 0
DFS lock handle其實就是enqueue，不過其是跨例項的請求。把4390005轉換出來，為CI 5。
DFS lock handle在RAC環境才發生，一般是在序列上的爭用/大量的TRUNC造成
接著分析程式，發現阻塞原因為：程式準備從CI2轉換為CI6，但是有1個程式持有CI6
SO: 0x5510db2d8, type: 18, owner: 0x5598b41f8, flag: INIT/-/-/0x00
----------enqueue 0x0x5510db2d8------------------------
lock version : 21023
Owner node : 1
grant_level : KJUSERNL
req_level : KJUSEREX
bast_level : KJUSERNL
notify_func : (nil)
resp : 0x4c35eeb50
procp : 0x5598b41f8
pid : 19054
proc version : 54
oprocp : (nil)
opid : 0
group lock owner : (nil)
xid : 0000-0000-00000000
dd_time : 0.0 secs
dd_count : 0
timeout : 0.0 secs
On_timer_q? : N
On_dd_q? : N
lock_state : OPENING CONVERTING
Open Options : KJUSERPROCESS_OWNED
Convert options : KJUSERNODEADLOCKWAIT KJUSERNODEADLOCKBLOCK
History : 0x1495149a
Msg_Seq : 0x0
res_seq : 506
valblk : 0x00000000000000000000000000000000 .
----------resource 0x0x4c35eeb50----------------------
resname : [0x1e][0x5],[CI]
Local node : 1
dir_node : 0
master_node : 0
hv idx : 102
hv last r.inc : 12
current inc : 12
hv status : 0
hv master : 0
open options :
Held mode : KJUSEREX
Cvt mode : KJUSERNL
Next Cvt mode : KJUSERNL
msg_seq : 0x1
res_seq : 506
grant_bits : KJUSERNL KJUSEREX
grant mode : KJUSERNL KJUSERCR KJUSERCW KJUSERPR KJUSERPW KJUSEREX
count : 2 0 0 0 0 1
val_state : KJUSERVS_NOVALUE
valblk : 0x00000000000000000000000000000000 .
access_node : 1
vbreq_state : 0
state : x8
resp : 0x4c35eeb50
On Scan_q? : N
cache level : 1
Total accesses: 30124
Imm. accesses: 3705
Granted_locks : 1
Cvting_locks : 2
value_block: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
GRANTED_Q :
lp 0x54e0da060 gl KJUSEREX rp 0x4c35eeb50 [0x1e][0x5],[CI]
master 0 pid 23479 bast 0 rseq 506 mseq 0 history 0x49a51495
open opt KJUSERPROCESS_OWNED
CONVERT_Q:
lp 0x5510db2d8 gl KJUSERNL rl KJUSEREX rp 0x4c35eeb50 [0x1e][0x5],[CI]
master 0 pid 19054 bast 0 rseq 506 mseq 0 history 0x1495149a
convert opt KJUSERNODEADLOCKWAIT KJUSERNODEADLOCKBLOCK
lp 0x54f0ec3a8 gl KJUSERNL rl KJUSEREX rp 0x4c35eeb50 [0x1e][0x5],[CI]
master 0 pid 19516 bast 0 rseq 506 mseq 0 history 0x1495149a
convert opt KJUSERNODEADLOCKWAIT KJUSERNODEADLOCKBLOCK
在向下分析，程式在dc_sequences這個row cache enqueue上請求X鎖
SO: 0x52ce82288, type: 50, owner: 0x54178fee8, flag: INIT/-/-/0x00
row cache enqueue: count=1 session=0x55bc76f08 bject=0x55e9eac48, request=X
savepoint=0x148f
row cache parent object: address=0x55e9eac48 cid=13(dc_sequences)
hash=9649e7e typ=11 transaction=(nil) flags=00000000
wn=0x55e9ead18[0x55e9ead18,0x55e9ead18] wat=0x55e9ead28[0x52ce822b8,0x52ce822b8] mode=N
status=-/-/-/-/-/-/-/-/-
request=X release=FALSE flags=2
instance lock id=QN 010cdbb3 b3b24847
data=
00000104 00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000
接著分析，發現對爭用的SEQ進行了DUMP，DUMP的物件ID為260，在其他庫查詢發現為ORA_TQ_BASE$
SO: 0x541b5ac58, type: 48, owner: 0x3d8abfbf8, flag: INIT/-/-/0x00
Sequence State Object:
kdnssflg =
kdnsshiw = INACTIVE
kdnsssqn = 0x46c83e3b0
KGL Sequence Object #260:
kdnsqflg =
kqdsnflg = KQDSNCYC KQDSNNOC
kdnsqcus = 0
kdnsqisp INACTIVE
Increment = +1
Minvalue = +1
Maxvalue = +4294967
Cachesize = +0
Highwater = +789773
Nextvalue = ###############################
以關鍵字 ORA_TQ_BASE$ 搜尋MOS，發現Bug 6027068 - Contention on ORA_TQ_BASE sequence [ID 6027068.8]
文件指出，該序列用於並行操作，預設使用nocache建立，導致了不必要的row cache contention。比對自己同版本的庫，該序列確實使用nocache的方式建立的
ass109.awk格式化Systemstats後發現，主要會話在等待cursor: pin S wait on X。
搜尋 [ waiting for ‘cursor: pin S wait on X’ ]，大量會話等待的資源都相同
為驗證，接著搜尋[ idn=.*value= ]。根據資訊確定其等待的資源為943724ff，阻塞者為SID 3137，其以Exclusive持有該Mutex
搜尋 [ Mutex.*943724ff ]，發現大量會話在其上請求Shared鎖，而Process 134（SID 3137）在上面持有Exclusive
KGX Atomic Operation Log 0x4aebe8aa0
Mutex 0x508397d00(3137, 0) idn 943724ff oper EXCL
Cursor Pin uid 3137 efd 0 whr 1 slp 0
pr=3 pso=0x4c3043b18 flg=0
pcs=0x508397d00 nxt=(nil) flg=34 cld=0 hd=0x3b8d004f8 par=0x5083980f0
ct=0 hsh=0 unp=(nil) unn=0 hvl=83983c8 nhv=1 ses=0x55bc76f08
hep=0x508397d80 flg=80 ld=1 b=0x5083972d0 ptr=0x40d96e2d0 fex=0x40d96d5e0
檢查Process 134，發現其在等待 DFS lock handle
PROCESS 134:
----------------------------------------
SO: 0x55a1646f8, type: 2, owner: (nil), flag: INIT/-/-/0x00
(process) Oracle pid=134, calls cur/top: 0x52ac62ef8/0x5053a18c8, flag: (0) -
int error: 0, call error: 0, sess error: 0, txn error 0
(post info) last post received: 0 0 172
last post received-location: kqrbpr: post after requeueing
last process to post me: 55a148c38 1 6
last post sent: 0 0 90
last post sent-location: KJCS Post snd proxy to flush msg
last process posted by me: 55a144cf8 1 6
(latch info) wait_event=0 bits=0
Process Group: DEFAULT, pseudo proc: 0x55b43ce00
O/S info: user: oracle, term: UNKNOWN, ospid: 19054
OSD pid info: Unix process pid: 19054, image: oracle@nc02
*** 2010-09-27 10:05:47.633
Short stack dump:
ksdxfstk()+32
----------------------------------------
SO: 0x55bc76f08, type: 4, owner: 0x55a1646f8, flag: INIT/-/-/0x00
(session) sid: 3137 trans: (nil), creator: 0x55a1646f8, flag: (41) USR/- BSY/-/-/-/-/-
DID: 0002-0086-00000049, short-term DID: 0002-0086-0000004A
txn branch: (nil)
oct: 3, prv: 0, sql: 0x49b8c2830, psql: 0x4b5d062a0, user: 33/BBG519
service name: ncrac
O/S info: user: Administrator, term: , ospid: 1234, machine: bbgapp01
program:
waiting for 'DFS lock handle' blocking sess=0x(nil) seq=2106 wait_time=0 seconds since wait started=3021
type|mode=43490005, id1=1e, id2=5
Dumping Session Wait History
for 'DFS lock handle' count=1 wait_time=1944973
type|mode=43490005, id1=1e, id2=5
for 'DFS lock handle' count=1 wait_time=489249
type|mode=43490005, id1=1e, id2=5
for 'DFS lock handle' count=1 wait_time=489252
type|mode=43490005, id1=1e, id2=5
for 'DFS lock handle' count=1 wait_time=489234
type|mode=43490005, id1=1e, id2=5
for 'DFS lock handle' count=1 wait_time=489263
type|mode=43490005, id1=1e, id2=5
for 'DFS lock handle' count=1 wait_time=489249
type|mode=43490005, id1=1e, id2=5
for 'DFS lock handle' count=1 wait_time=489235
type|mode=43490005, id1=1e, id2=5
for 'DFS lock handle' count=1 wait_time=489252
type|mode=43490005, id1=1e, id2=5
for 'DFS lock handle' count=1 wait_time=489259
type|mode=43490005, id1=1e, id2=5
for 'DFS lock handle' count=1 wait_time=489253
type|mode=43490005, id1=1e, id2=5
temporary object counter: 0
DFS lock handle其實就是enqueue，不過其是跨例項的請求。把4390005轉換出來，為CI 5。
DFS lock handle在RAC環境才發生，一般是在序列上的爭用/大量的TRUNC造成
接著分析程式，發現阻塞原因為：程式準備從CI2轉換為CI6，但是有1個程式持有CI6
SO: 0x5510db2d8, type: 18, owner: 0x5598b41f8, flag: INIT/-/-/0x00
----------enqueue 0x0x5510db2d8------------------------
lock version : 21023
Owner node : 1
grant_level : KJUSERNL
req_level : KJUSEREX
bast_level : KJUSERNL
notify_func : (nil)
resp : 0x4c35eeb50
procp : 0x5598b41f8
pid : 19054
proc version : 54
oprocp : (nil)
opid : 0
group lock owner : (nil)
xid : 0000-0000-00000000
dd_time : 0.0 secs
dd_count : 0
timeout : 0.0 secs
On_timer_q? : N
On_dd_q? : N
lock_state : OPENING CONVERTING
Open Options : KJUSERPROCESS_OWNED
Convert options : KJUSERNODEADLOCKWAIT KJUSERNODEADLOCKBLOCK
History : 0x1495149a
Msg_Seq : 0x0
res_seq : 506
valblk : 0x00000000000000000000000000000000 .
----------resource 0x0x4c35eeb50----------------------
resname : [0x1e][0x5],[CI]
Local node : 1
dir_node : 0
master_node : 0
hv idx : 102
hv last r.inc : 12
current inc : 12
hv status : 0
hv master : 0
open options :
Held mode : KJUSEREX
Cvt mode : KJUSERNL
Next Cvt mode : KJUSERNL
msg_seq : 0x1
res_seq : 506
grant_bits : KJUSERNL KJUSEREX
grant mode : KJUSERNL KJUSERCR KJUSERCW KJUSERPR KJUSERPW KJUSEREX
count : 2 0 0 0 0 1
val_state : KJUSERVS_NOVALUE
valblk : 0x00000000000000000000000000000000 .
access_node : 1
vbreq_state : 0
state : x8
resp : 0x4c35eeb50
On Scan_q? : N
cache level : 1
Total accesses: 30124
Imm. accesses: 3705
Granted_locks : 1
Cvting_locks : 2
value_block: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
GRANTED_Q :
lp 0x54e0da060 gl KJUSEREX rp 0x4c35eeb50 [0x1e][0x5],[CI]
master 0 pid 23479 bast 0 rseq 506 mseq 0 history 0x49a51495
open opt KJUSERPROCESS_OWNED
CONVERT_Q:
lp 0x5510db2d8 gl KJUSERNL rl KJUSEREX rp 0x4c35eeb50 [0x1e][0x5],[CI]
master 0 pid 19054 bast 0 rseq 506 mseq 0 history 0x1495149a
convert opt KJUSERNODEADLOCKWAIT KJUSERNODEADLOCKBLOCK
lp 0x54f0ec3a8 gl KJUSERNL rl KJUSEREX rp 0x4c35eeb50 [0x1e][0x5],[CI]
master 0 pid 19516 bast 0 rseq 506 mseq 0 history 0x1495149a
convert opt KJUSERNODEADLOCKWAIT KJUSERNODEADLOCKBLOCK
在向下分析，程式在dc_sequences這個row cache enqueue上請求X鎖
SO: 0x52ce82288, type: 50, owner: 0x54178fee8, flag: INIT/-/-/0x00
row cache enqueue: count=1 session=0x55bc76f08 bject=0x55e9eac48, request=X
savepoint=0x148f
row cache parent object: address=0x55e9eac48 cid=13(dc_sequences)
hash=9649e7e typ=11 transaction=(nil) flags=00000000
wn=0x55e9ead18[0x55e9ead18,0x55e9ead18] wat=0x55e9ead28[0x52ce822b8,0x52ce822b8] mode=N
status=-/-/-/-/-/-/-/-/-
request=X release=FALSE flags=2
instance lock id=QN 010cdbb3 b3b24847
data=
00000104 00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000
接著分析，發現對爭用的SEQ進行了DUMP，DUMP的物件ID為260，在其他庫查詢發現為ORA_TQ_BASE$
SO: 0x541b5ac58, type: 48, owner: 0x3d8abfbf8, flag: INIT/-/-/0x00
Sequence State Object:
kdnssflg =
kdnsshiw = INACTIVE
kdnsssqn = 0x46c83e3b0
KGL Sequence Object #260:
kdnsqflg =
kqdsnflg = KQDSNCYC KQDSNNOC
kdnsqcus = 0
kdnsqisp INACTIVE
Increment = +1
Minvalue = +1
Maxvalue = +4294967
Cachesize = +0
Highwater = +789773
Nextvalue = ###############################
以關鍵字 ORA_TQ_BASE$ 搜尋MOS，發現Bug 6027068 - Contention on ORA_TQ_BASE sequence [ID 6027068.8]
文件指出，該序列用於並行操作，預設使用nocache建立，導致了不必要的row cache contention。比對自己同版本的庫，該序列確實使用nocache的方式建立的
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/8242091/viewspace-736144/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- SystemState分析案例（一）
- zt_systemstate案例分析
- 【中亦安圖】Systemstate Dump分析經典案例（7）
- 【中亦安圖】Systemstate Dump分析經典案例（8）
- 如何理解systemstate dump
- 偽三元表示式 效能分析案例
- Oracle資料庫效能障礙分析利器：SYSTEMSTATE DUMP介紹Oracle資料庫
- 搶紅包案例分析以及程式碼實現（三）
- 備庫報警郵件的分析案例(三)
- AWR報告分析之三：cursor: pin S 的原理與案例分析
- 案例分析
- AWR報告分析之三：cursor: pin S 的原理與案例分析-eygle
- 遊戲資料分析的三大實戰案例深度解讀遊戲
- 基於oracle11g生成systemstate dump檔案分析持鎖會話有等待鎖會話及閂latch之系列三Oracle會話
- jemeter分析(二) — jmeter案例分析JMeter
- 超市管理案例分析
- 死鎖案例分析
- 故障分析 | MySQL死鎖案例分析MySql
- EOS原始碼分析(3)案例分析原始碼
- nginx 常用配置案例（三）Nginx
- Hadoop學習筆記—20.網站日誌分析專案案例（三）統計分析Hadoop筆記網站
- Mysql之案例分析（一）MySql
- 層次分析小案例
- MySQL經典案例分析MySql
- oracle SPA 效能分析案例Oracle
- 《畫家鄉》案例分析
- UI設計案例分析UI
- 案例分析習題2
- GreatSQL 死鎖案例分析SQL
- 【MySQL】死鎖案例之三MySql
- Oracle分析函式七——分析函式案例Oracle函式
- 不能連線資料庫收集Systemstate Dumps資訊資料庫
- 利用hanganalyz/systemstate dump診斷資料庫hang資料庫
- SQL效能優化案例分析SQL優化
- DRM 分析及案例講解
- logminer 日誌分析案例
- itpub awr案例分析之一
- [轉] Android 效能分析案例Android