- 最后登录
- 2023-8-16
- 在线时间
- 1686 小时
- 威望
- 2135
- 金钱
- 50532
- 注册时间
- 2011-10-12
- 阅读权限
- 200
- 帖子
- 5207
- 精华
- 39
- 积分
- 2135
- UID
- 2
|
2#
发表于 2012-2-9 19:45:15
ODM Finding:
*** 2012-01-20 03:52:15.042
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! <<<
row cache enqueue: session: 70000033933c2b8, mode: N, request: S
SO: 70000033933c2b8, type: 4, owner: 70000033924d378, flag: INIT/-/-/0x00
(session) sid: 517 trans: 0, creator: 70000033924d378, flag: (100041) USR/- BSY/-/-/-/-/-
DID: 0002-001F-00000002, short-term DID: 0002-001F-00000003
txn branch: 0
oct: 3, prv: 0, sql: 70000032bcf3358, psql: 70000032bcf3358, user: 0/SYS
service name: SYS$USERS
O/S info: user: oracle, term: , ospid: 1687624, machine: GKdb2
program: racgimon@GKdb2 (TNS V1-V3)
application name: racgimon@GKdb2 (TNS V1-V3), hash value=3775208945
last wait for 'ksdxexeotherwait' blocking sess=0x0 seq=6236 wait_time=2 seconds since wait started=18
=0, =0, =0
racgimon@GKdb2 (TNS V1-V3) wait for ROW CACHE ENQUEUE LOCK!
racgimon 是RAC中监控 instance的进程,
SO: 70000032cfe6358, type: 53, owner: 70000033933c2b8, flag: INIT/-/-/0x00
LIBRARY OBJECT LOCK: lock=70000032cfe6358 handle=70000032bcf3358 mode=N
call pin=0 session pin=0 hpc=0000 hlc=0000
htl=70000032cfe63d8[70000032aae7c18,70000032aae7c18] htb=70000032aae7c18 ssga=70000032aae6c10
user=70000033933c2b8 session=70000033933c2b8 count=1 flags=[0000] savepoint=0x4f186a0d
LIBRARY OBJECT HANDLE: handle=70000032bcf3358 mtx=70000032bcf3488(2) cdp=2
name=select DECODE(UPPER(d.OPEN_MODE),'READ WRITE','R','N') ,DECODE(UPPER(i.STATUS),'OPEN','O','N') into :b0,:b1 from v$database d ,gv$instance i where i.INSTAN
CE_NAME=:b2
hash=23b6ea0ac674d70a775ed8ffdba461ef timestamp=01-16-2012 19:46:39
namespace=CRSR flags=RON/KGHP/TIM/KEP/PN0/MED/KST/DBN/MTX/[508100d0]
kkkk-dddd-llll=0041-0001-0001 lock=N pin=0 latch#=4 hpc=251e hlc=251e
lwt=70000032bcf3400[70000032bcf3400,70000032bcf3400] ltm=70000032bcf3410[70000032bcf3410,70000032bcf3410]
pwt=70000032bcf33c8[70000032bcf33c8,70000032bcf33c8] ptm=70000032bcf33d8[70000032bcf33d8,70000032bcf33d8]
ref=70000032bcf3430[70000032bcf3430,70000032bcf3430] lnd=70000032bcf3448[70000032bcf3448,70000032bcf3448]
LIBRARY OBJECT: object=70000032bcf2e88
type=CRSR flags=EXS[0001] pflags=[0000] status=VALD load=0
CHILDREN: size=16
child# table reference handle
------ -------- --------- --------
0 70000032bcf2950 70000032bcf25c0 70000032bcf2428
1 70000032bcf2950 70000032bcf2858 70000032bce6bc8
DATA BLOCKS:
data# heap pointer status pins change whr
----- -------- -------- --------- ---- ------ ---
0 70000032bcf3298 70000032bcf2fa0 I/P/A/-/- 0 NONE 00
racgimon 正在解析的语句是
select DECODE(UPPER(d.OPEN_MODE),'READ WRITE','R','N') ,DECODE(UPPER(i.STATUS),'OPEN','O','N') into :b0,:b1 from v$database d ,gv$instance i where i.INSTANCE_NAME=:b2
SO: 70000033924d378, type: 2, owner: 0, flag: INIT/-/-/0x00
(process) Oracle pid=31, calls cur/top: 70000032aae66a8/70000032aae66a8, flag: (0) -
int error: 0, call error: 0, sess error: 0, txn error 0
(post info) last post received: 0 0 55
last post received-location: kjata: wake up enqueue owner
last process to post me: 70000033a2293a8 1 6
last post sent: 0 0 24
last post sent-location: ksasnd
last process posted by me: 70000033b236468 1 6
(latch info) wait_event=0 bits=0
Process Group: DEFAULT, pseudo proc: 7000003392875d0
O/S info: user: oracle, term: UNKNOWN, ospid: 2121752
OSD pid info: Unix process pid: 2121752, image: oracle@GKdb2 (TNS V1-V3)
Short stack dump:
ksdxfstk+002c<-ksdxdocmdmult+0fc4<-ksudmp_proc+02ac<-ksudss+0724<-kqrigt+0568<-kqrpre1+0960<-kqrpre+001c<-koknmpn+01ac<-opikod+04c0<-opiodr+0ae0<-ttcpip+1020<-opitsk+1
124<-opiino+0990<-opiodr+0ae0<-opidrv+0484<-sou2o+0090<-opimai_real+01bc<-main+0098<-__start+0098
PID=31
ASS.AWK analysis- [oracle@vrh8 ~]$ awk -f ass109.awk.1 cwgkvpd2_ora_2121752.trc
- Starting Systemstate 1
- ...............................................
- Ass.Awk Version 1.0.9 - Processing cwgkvpd2_ora_2121752.trc
- System State 1
- ~~~~~~~~~~~~~~~~
- 1:
- 2: waiting for 'pmon timer' wait
- 3: waiting for 'DIAG idle wait' wait
- 4: waiting for 'rdbms ipc message' wait
- 5: waiting for 'rdbms ipc message' wait
- 6: waiting for 'ges remote message' wait
- 7: waiting for 'gcs remote message' wait
- 8: waiting for 'gcs remote message' wait
- 9: waiting for 'gcs remote message' wait
- 10: waiting for 'gcs remote message' wait
- 11: waiting for 'rdbms ipc message' wait
- 12: waiting for 'rdbms ipc message' wait
- 13: waiting for 'rdbms ipc message' wait
- 14: waiting for 'rdbms ipc message' wait
- 15: waiting for 'rdbms ipc message' wait
- 16: waiting for 'cursor: pin S wait on X' wait
- 17: waiting for 'cursor: pin S wait on X' wait
- 18: waiting for 'cursor: pin S wait on X' wait
- 19: waiting for 'rdbms ipc reply' wait
- 20: waiting for 'rdbms ipc message' wait
- 21: waiting for 'latch: row cache objects'[Latch 70000032f912408] wait
- 22: waiting for 'cursor: pin S wait on X' wait
- 23: waiting for 'rdbms ipc message' wait
- 24: waiting for 'rdbms ipc message' wait
- 25: waiting for 'latch: row cache objects'[Rcache object=700000328d14fe0,] wait
- Cmd: Select
- 26: waiting for 'Streams AQ: qmn coordinator idle wait' wait
- 27: waiting for 'latch: row cache objects'[Rcache object=7000002b6df0ab0,] wait
- 29: waiting for 'SQL*Net message from client' wait
- 30: waiting for 'latch: row cache objects'[Rcache object=7000002cdc4a358,] wait
- 31: last wait for 'ksdxexeotherwait' [Rcache object=7000002dae97c58,]
- Cmd: Select
- 32: last wait for 'latch: row cache objects'
- Cmd: PL/SQL Execute
- 33: waiting for 'SQL*Net message from client' wait
- 34: waiting for 'cursor: pin S wait on X' wait
- 35: waiting for 'latch: row cache objects'[Rcache object=700000328950f28,] wait
- 37: waiting for 'cursor: pin S wait on X' wait
- 38: waiting for 'cursor: pin S wait on X' wait
- 39: waiting for 'cursor: pin S wait on X' wait
- 40: waiting for 'cursor: pin S wait on X' wait
- 41: waiting for 'cursor: pin S wait on X' wait
- 42: waiting for 'latch: row cache objects'[Rcache object=7000002cdb335c8,] wait
- 43: for 'Streams AQ: waiting for time management or cleanup tasks' wait
- 44: waiting for 'Streams AQ: qmn slave idle wait' wait
- 45:
- 46: waiting for 'cursor: pin S wait on X' wait
- 47: waiting for 'cursor: pin S wait on X' wait
- 48: waiting for 'cursor: pin S wait on X' wait
- 50: waiting for 'cursor: pin S wait on X' wait
- Blockers
- ~~~~~~~~
- Above is a list of all the processes. If they are waiting for a resource
- then it will be given in square brackets. Below is a summary of the
- waited upon resources, together with the holder of that resource.
- Notes:
- ~~~~~
- o A process id of '???' implies that the holder was not found in the
- systemstate.
- Resource Holder State
- Latch 70000032f912408 ??? Blocker
- Rcache object=700000328d14fe0, ??? Blocker
- Rcache object=7000002b6df0ab0, ??? Blocker
- Rcache object=7000002cdc4a358, ??? Blocker
- Rcache object=7000002dae97c58, ??? Blocker
- Rcache object=700000328950f28, ??? Blocker
- Rcache object=7000002cdb335c8, ??? Blocker
- Object Names
- ~~~~~~~~~~~~
- Latch 70000032f912408 Child row cache objects
- Rcache object=700000328d14fe0,
- Rcache object=7000002b6df0ab0,
- Rcache object=7000002cdc4a358,
- Rcache object=7000002dae97c58,
- Rcache object=700000328950f28,
- Rcache object=7000002cdb335c8,
- 231196 Lines Processed.
复制代码 因为是RAC环境,且不是267 level的systemstate dump 所以部分Rcache object的holder 不可知。
其他服务进程的一些信息:
PID=35
PROCESS 35:
----------------------------------------
SO: 70000033924db58, type: 2, owner: 0, flag: INIT/-/-/0x00
(process) Oracle pid=35, calls cur/top: 7000003282dd728/70000032cfe18b0, flag: (0) -
int error: 0, call error: 0, sess error: 0, txn error 0
(post info) last post received: 0 0 163
last post received-location: kqrbtm
last process to post me: 70000033b236468 1 6
last post sent: 0 0 24
last post sent-location: ksasnd
last process posted by me: 70000033b236468 1 6
(latch info) wait_event=0 bits=0
Process Group: DEFAULT, pseudo proc: 7000003392875d0
O/S info: user: oracle, term: UNKNOWN, ospid: 2191584
OSD pid info: Unix process pid: 2191584, image: oracle@GKdb2
Short stack dump:
ksdxfstk+002c<-ksdxcb+04e4<-sspuser+0074<-000044C0<-skgpwwait+00bc<-ksliwat+06c0<-kslwaitns_timed+0024<-kskthbwt+022c<-kslwait+00f4<-kqrigt+05e0<-kqrpre1+0960<-kqrpre+
001c<-kkercs+0244<-kkehrd+0e1c<-kkoarl+0350<-kkoiqb+5838<-kkooqb+0a40<-kkoqbc+20ac<-apakkoqb+0084<-apaqbdDescendents+03d4<-apaqbdListReverse+006c<-apaqbd+000c<-apadrv+
045c<-opitca+13fc<-kksFullTypeCheck+001c<-rpiswu2+034c<-kksSetBindType+0d28<-kksfbc+1054<-opiexe+098c<-opiefn0+0198<-opiefn+00dc<-opiall0+0c0c<-opikpr+02cc<-opiodr+0ae
0<-rpidrus+01bc<-skgmstack+00c8<-rpidru+0088<-rpiswu2+034c<-kprball+06a4<-kkpolpd_load_part_descr+02e4<-kqlctxlod+0094<-kqllod+1a54<-kglobld+05ac<-kglobpn+09f8<-kglpim
+0294<-kglpin+0e60<-kkdllpoOpt+095c<-kkdllpo+003c<-kokliccx+0084<-kokacmc+0070<-kksLoadChild+0f78<-kkslod+0120<-kglobld+05ac<-kglobpn+09f8<-kglpim+0294<-kglpin+0e60<-k
xsGetRuntimeLock+0458<-kksfbc+28b0<-kkspsc0+0ffc<-kokapvpr+02a8<-kokacau+06b0<-kokasuc+0104<-kokavpr+01e4<-koklcprv+03b4<-koklpgsz+00f4<-kpolob+13bc<-opiodr+0ae0<-ttcp
ip+1020<-opitsk+1124<-opiino+0990<-opiodr+0ae0<-opidrv+0484<-sou2o+0090<-opimai_real+01bc<-main+0098<-__start+0098
SO: 70000033c334d40, type: 4, owner: 70000033924db58, flag: INIT/-/-/0x00
(session) sid: 514 trans: 0, creator: 70000033924db58, flag: (100041) USR/- BSY/-/-/-/-/-
DID: 0002-0023-00000378, short-term DID: 0002-0023-00000377
txn branch: 0
oct: 0, prv: 0, sql: 7000002ec963e18, psql: 700000328700c70, user: 72/NBI
service name: SYS$USERS
O/S info: user: , term: , ospid: 1234, machine: dccwbak
program:
waiting for 'latch: row cache objects' blocking sess=0x0 seq=2894 wait_time=0 seconds since wait started=0
address=70000032f912408, number=c8, tries=0
Dumping Session Wait History
for 'row cache lock' count=1 wait_time=2759215
cache id=10, mode=0, request=3
for 'latch: row cache objects' count=1 wait_time=59490
address=70000032f912408, number=c8, tries=0
for 'row cache lock' count=1 wait_time=2929707
cache id=10, mode=0, request=3
for 'latch: row cache objects' count=1 wait_time=47825
address=70000032f912408, number=c8, tries=0
for 'row cache lock' count=1 wait_time=2929706
cache id=10, mode=0, request=3
for 'latch: row cache objects' count=1 wait_time=16640
address=70000032f912408, number=c8, tries=0
for 'row cache lock' count=1 wait_time=2929706
cache id=10, mode=0, request=3
for 'latch: row cache objects' count=1 wait_time=72580
address=70000032f912408, number=c8, tries=0
for 'row cache lock' count=1 wait_time=2929704
cache id=10, mode=0, request=3
for 'latch: row cache objects' count=1 wait_time=33290
address=70000032f91
SO: 7000003282dd728, type: 3, owner: 70000032cfe7628, flag: INIT/-/-/0x00
(call) sess: cur 700000339336d18, rec 700000339336d18, usr 70000033c334d40; depth: 2
----------------------------------------
SO: 7000002e5240638, type: 50, owner: 7000003282dd728, flag: INIT/-/-/0x00
row cache enqueue: count=1 session=70000033c334d40 object=700000328950f28, request=S
savepoint=0x3df76
row cache parent object: address=700000328950f28 cid=16(dc_histogram_defs)
hash=32f645c6 typ=11 transaction=0 flags=00000000
own=700000328950ff8[700000328950ff8,700000328950ff8] wat=700000328951008[7000002e5240668,7000002e5240668] mode=N
status=-/-/-/-/-/-/-/-/-
request=N release=FALSE flags=4
instance lock id=QQ 355e72a6 feac22e5
set=0, complete=FALSE
set=1, complete=FALSE
data=
00000106 00060000 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 00000000 00000000 00000000
00000000 00000000
就等待事件来看 这个实例存在大量的硬解析 , row cache lock的主要对象类别是 dc_histogram_defs 即 histogram信息。
建议你上传问题时段 这2个实例的AWR报告, 通过调优解析来 避免row cache lock hang。 |
|