首页 » Cloud, ORACLE 9i-23ai » Oracle 19c hang ‘TTnn Sleep 10 seconds and then try to clear SRLs in N time(s)’ wait ‘row cache lock’ & ‘cursor: pin S wait on X’
Oracle 19c hang ‘TTnn Sleep 10 seconds and then try to clear SRLs in N time(s)’ wait ‘row cache lock’ & ‘cursor: pin S wait on X’
环境oracle 19c(19.7) on linux, 数据库做了failover后在open resetlogs数据库时，等待了很久的时间，数据库里查询wait event是’row cache lock’ & ‘cursor: pin S wait on X’， DB alert log显示下面的信息:
Note:
可以看到不断的在输出TTnn Sleep 10 seconds and then try to clear SRLs in N time(s)， TTnn进程为异步模式下的REDO传输进程， 在清理standby redo log时hang, 还出现了row cache enqueue生成了SSD（system state dump）trace, 下面分析trace内容。
分析SSD trace是个烧脑的过程，可以先看汇总信息再看明细，首先是ass 脚本
oracle@oel7db1 SSD]$ awk -f ass1046.awk anbob_p001_47286.trc
awk: ass1046.awk:463: warning: escape sequence `\+' treated as plain `+'
Starting Systemstate 1
..............................................................................
...............................................................................
........................................................
Ass.Awk Version 1.0.46
~~~~~~~~~~~~~~~~~~~~~~
Source file : anbob_p001_47286.trc
System State 1 (2021-12-24 16:29:12.304)
~~~~~~~~~~~~~~ ~~~~~~~~~~~~~~~~~~~~~~~
1:
2:
3: waiting for 'pmon timer'
4: waiting for 'rdbms ipc message'
5: waiting for 'VKTM Logical Idle Wait'
6: waiting for 'rdbms ipc message'
7: waiting for 'rdbms ipc message'
8: waiting for 'SQL*Net message from client'
...
47: waiting for 'Data Guard: Gap Manager'
48: waiting for 'Data Guard: Timer'
49: waiting for 'PX Deq: Txn Recovery Reply'
Cmd: Unknown(35)
50: waiting for 'heartbeat redo informer'
51: waiting for 'Data Guard: rtrt work'
52: waiting for 'cursor: pin S wait on X'[Mutex 4d078f90]
Final Blocker: inst: 1, sid: 5036, ser: 11929
53: waiting for 'row cache lock' [Rcache object=0xcb7e8b50,]
Cmd: Update
54: waiting for 'cursor: pin S wait on X'[Mutex 4d078f90]
Final Blocker: inst: 1, sid: 5036, ser: 11929
55: waiting for 'cursor: pin S wait on X'[Mutex 4d078f90]
Final Blocker: inst: 1, sid: 5036, ser: 11929
56: waiting for 'cursor: pin S wait on X'[Mutex 4d078f90]
Final Blocker: inst: 1, sid: 5036, ser: 11929
57: waiting for 'cursor: pin S wait on X'[Mutex 4d078f90]
Final Blocker: inst: 1, sid: 5036, ser: 11929
58: waiting for 'cursor: pin S wait on X'[Mutex 4d078f90]
Final Blocker: inst: 1, sid: 5036, ser: 11929
59: waiting for 'cursor: pin S wait on X'[Mutex 4d078f90]
Final Blocker: inst: 1, sid: 5036, ser: 11929
60: waiting for 'cursor: pin S wait on X'[Mutex 4d078f90]
Final Blocker: inst: 1, sid: 5036, ser: 11929
...
78: waiting for 'cursor: pin S wait on X'[Mutex 4d078f90]
Final Blocker: inst: 1, sid: 287, ser: 3759
79: waiting for 'cursor: pin S wait on X'[Mutex 4d078f90]
Final Blocker: inst: 1, sid: 287, ser: 3759
80: waiting for 'cursor: pin S wait on X'[Mutex 4d078f90]
Final Blocker: inst: 1, sid: 287, ser: 3759
81: waiting for 'cursor: pin S wait on X'[Mutex 4d078f90]
Final Blocker: inst: 1, sid: 287, ser: 3759
82: waiting for 'cursor: pin S wait on X'[Mutex 4d078f90]
Final Blocker: inst: 1, sid: 287, ser: 3759
83: waiting for 'cursor: pin S wait on X'[Mutex 4d078f90]
Final Blocker: inst: 1, sid: 5036, ser: 11929
84: waiting for 'cursor: pin S wait on X'[Mutex 4d078f90]
Final Blocker: inst: 1, sid: 287, ser: 3759
85: waiting for 'cursor: pin S wait on X'[Mutex 4d078f90]
Final Blocker: inst: 1, sid: 287, ser: 3759
86: waiting for 'cursor: pin S wait on X'[Mutex 4d078f90]
Final Blocker: inst: 1, sid: 287, ser: 3759
87: waiting for 'cursor: pin S wait on X'[Mutex 4d078f90]
...
Resource Holder State
Mutex 4d078f90 53: 53: is waiting for 83:
Rcache object=0xcb7e8b50, 83: 83: is waiting for 53:
PID to SID Mapping
~~~~~~~~~~~~~~~~~~
Pid 53 maps to Sid(s): 5036 5038
Pid 83 maps to Sid(s): 287 290
Object Names
~~~~~~~~~~~~
Mutex 4d078f90
Rcache object=0xcb7e8b50, cid=3(dc_rollback_segments)
Summary of Wait Events Seen (count>10)
~~~~~~~~~~~~~~~~~~~~~~~~~~~
No wait events seen more than 10 times
Note:
大量的cursor: pin S wait on X等待，SQL并发解析等待，大量会话在等SID 5036和287, 再看resource holder是产生了deadlock, PID 53等83 mutex, 83等53 row cache obj,cache_id=3 dc_rollback_segments.
除了ass脚本，Oracle还有一个工具STRA， 格式也不错。
1.0 WAIT EVENTS: Summary of all current wait events for all sessions found in the System State Dump.
HOWTO: Look for wait events related to your issue OR any other that can block or slown down the database.
=================================================================================================================================================
Occurence Wait Event
--------- ----------
159 cursor: pin S wait on X
26 rdbms ipc message
5 Space Manager: slave idle wait
2 watchdog main loop
1 wait for unread message on broadcast channel
1 VKTM Logical Idle Wait
1 VKRM Idle
1 SQL*Net message from client
1 smon timer
1 row cache lock
1 PX Deq: Txn Recovery Reply
1 pmon timer
1 pman timer
1 OFS idle
1 lreg timer
1 heartbeat redo informer
1 DIAG idle wait
1 Data Guard: Timer
1 Data Guard: rtrt work
1 Data Guard: Gap Manager
2.1 FINAL BLOCKERS: Final Blockers and Occurances.
HOWTO: Look for the blockers that have more occurrencies which means that those sessions are holding more waiters in the database, but keep in mind
that they are not ROOT blockers or FINAL blockers. Some of them might have or not another blocker which would be also listed here.
==================================================================================
Occurrence Blocker
---------- ---------
87 inst: 1, sid: 287, ser: 3759
72 inst: 1, sid: 5036, ser: 11929
2.3 FINAL BLOCKERS: Most likely final blockers found
HOWTO: All blockers that blocking at least one session that is not being blocked or do not have Dumping final blocker in the SSD. In case of Mutex issue the waiters might not appear in this section since the Dumping Final Blocker might not be in the SSD trace for those waiters.
go after MUTEXES section in this report. Start analyzing from the blockers that are holding more waiters per 2.2 FINAL BLOCKERS and 2.1 FINAL BLOCKERS sections.
Consider the time that the blocker is blocking the waiter in the section 3.0 BLOCKED SESSIONS. Keep in mind that deadlocks are not being showed here.
==================================================================================
Most likely a final blocker is 5036,11929
PROCESS 53: P001
SO: 0xafef0be8, type: process (2), map: 0xaf58e6b0
(process) Oracle pid:53, ser:4, calls cur/top: 0xb2341840/0xcb3bc308
flags : (0x0) - icon_uid:0 logon_pdbid=0
flags2: (0x1000), flags3: (0x10)
call error: 0, sess error: 0, txn error 0
intr queue: empty
(latch info) hold_bits=0x0 ud_influx=0x329
(osp latch info) hold_bits=0x0 ud_influx=0x0
Process Group: DEFAULT, pseudo proc: 0xad70acd0
O/S info: user: oracle, term: UNKNOWN, ospid: 47286
OSD pid info:
Short stack dump:
ksedsts()+426<-ksdxfstk()+58<-ksdxdocmdmultex()+6119<-ksdxdocmdmult()+55<-ksudmp_proc()+1594<-ksudss_main()+1976<-ksudss_opt()+1544<-kqrget()+3744<-kqrLockPo()+246<-kqrpre2()+1043<-kqrpre1()+40<-ktuGetRowCache1()+82<-ktuGetUsegDba()+598<-ktuGetCommitTimesMain_Int()+604<-ktuGetCommitTimesMain()+542<-ktuGetCommitTimes()+149<-ktbgcl1()+2482<-ktrgcm()+9998<-ktrget2()+971<-kdsgrp()+511<-qetlbr()+287<-qertbFetchByRowID()+1176<-opifch2()+3242<-opiall0()+1560<-opikpr()+595<-opiodr()+1202<-rpidrus()+198<-skgmstack()+65<-rpidru()+132<-rpiswu2()+543<-kprball()+1046<-kqdhsr()+1640<-kqrReadFromDB()+338<-kqrpre2()+1931<-kqrpre()+35<-kkestRCSBase()+458<-kkercs()+211<-kkehrd_prealo()+1059<-kkeaprWithFro()+894<-kkepslCompCtl()+907<-kkepsl()+35<-kkecdn()+1291<-kkotap()+16226<-kkoiqb()+9323<-kkooqb()+579<-kkoqbc()+2722<-apakkoqb()+159<-apaqbdDescendents()+488<-apaqbd()+140<-apadrv()+1236<-opitca()+2207<-kksFullTypeCheck()+81<-rpiswu2()+2004<-kksLoadChild()+7818<-kxsGetRuntimeLock()+1983<-kksfbc()+18320<-opiexe()+2834<-opiodr()+1202<-rpidrus()+198<-skgmstack()+65<-rpidru()+132<-rpiswu2()+543<-rpidrv()+1266<-rpiexe()+68<-ktsucr()+1565<-kqrCreateUsingSecondaryKey()+451<-kqrpre2()+3750<-kqrpre1()+40<-kklmsle()+140<-kkmupd()+1090<-opiprsdml()+783<-opiSem()+7418<-opiprs()+321<-kksParseChildCursor()+527<-rpiswu2()+2004<-kksLoadChild()+5283<-kxsGetRuntimeLock()+1983<-kksfbc()+18320<-kkspsc0()+1566<-kksParseCursor()+114<-opiosq0()+2330<-opiodr()+1202<-rpidrus()+198<-skgmstack()+65<-rpidru()+132<-rpiswu2()+543<-rpidrv()+1266<-rpisplu_internal()+474<-ktuscu()+294<-kqrcmt()+978<-ktcCommitTxn_new()+5261<-ktcCommitTxn()+94<-kturfptrSlaveWork()+869<-kturfptrSlaveMain()+762<-kxfprdp_int()+1915<-ksbdispatch()+365<-opirip()+522<-opidrv()+581<-sou2o()+165<-opimai_real()+173<-ssthrdmain()+417<-main()+256<-__libc_start_main()+245
(session) sid: 5036 ser: 11929 trans: 0x789674d0, creator: 0xaf58e6b0
flags: (0x41) USR/- flags2: (0x9) -/-/INC
flags_idl: (0x1) status: BSY/-/-/- kill: -/-/-/-
DID: 0001-0035-000000070000-0000-00000000, short-term DID:
txn branch: (nil)
edition#: 0 user#/name: 0/SYS
oct: 6, prv: 0, sql: 0xc4f3b268, psql: 0xc3e35de0
stats: 0xcb452d48, PX stats: 0x12a12c04
service name: SYS$USERS
client details:
O/S info: user: oracle, term: pts/0, ospid: 47286
machine: zdbm01 program: oracle@zdbm01 (P001)
Current Wait Stack:
0: waiting for 'row cache lock'
cache id=0x3, mode=0x0, request=0x3
wait_id=63 seq_num=165 snap_id=51
wait times: snap=0.052141 sec, exc=5 min 4 sec, total=5 min 7 sec
wait times: max=infinite, heur=5 min 7 sec
wait counts: calls=99 os=99
in_wait=1 iflags=0x15a2
There are 159 sessions blocked by this session.
Dumping one waiter:
inst: 1, sid: 5987, ser: 57799
wait event: 'cursor: pin S wait on X'
p1: 'idn'=0x4d078f90
p2: 'value'=0x13ac00000000
min_blocked_time: 2 secs, waiter_cache_ver: 97
Wait State:
fixed_waits=0 flags=0x23 boundary=(nil)/-1
==================================================================================
2.4 FINAL BLOCKERS: Getting the summarized information from blockers found as final blockers.
HOWTO: This section provides information about ALL blockers, not only the ROOT or FINAL ones. The most important thing is to verify if you have any BACKGROUND process
blocking others sessions. If you want to verify only the ROOT blockers of FINAL blockers to go 2.3 FINAL BLOCKERS section. This section also actually creates the blockers file.
Be aware that in same cases the blocker is not found in the SSD, so not details will be shown. Make sure if you are analyzing a RAC environment that you are following the correctly the sh stra.sh intructions.
==================================================================================
Occurrence Blocker
---------- ---------
87 inst: 1, sid: 287, ser: 3759
========= More details about the blocker =========
PROCESS 83: P00V
SO: 0xafef24f8, type: process (2), map: 0xaf5a2840
(process) Oracle pid:83, ser:1, calls cur/top: 0xb2344ef0/0xcabec0c0
flags : (0x0) - icon_uid:0 logon_pdbid=0
flags2: (0x0), flags3: (0x10)
call error: 0, sess error: 0, txn error 0
intr queue: empty
(latch info) hold_bits=0x0 ud_influx=0x5
Process Group: DEFAULT, pseudo proc: 0xad70acd0
O/S info: user: oracle, term: UNKNOWN, ospid: 47347
OSD pid info:
Short stack dump:
ksedsts()+426<-ksdxfstk()+58<-ksdxcb()+872<-sspuser()+200<-__sighandler()<-__select()+19<-skgpwwait()+420<-kgxWait()+836<-kgxSharedExamine()+785<-kxsGetRuntimeLock()+246<-kkscsCheckCursor()+550<-kkscsSearchChildList()+1324<-kksfbc()+15645<-kkspsc0()+1566<-kksParseCursor()+114<-opiosq0()+2330<-opiodr()+1202<-rpidrus()+198<-skgmstack()+65<-rpidru()+132<-rpiswu2()+543<-rpidrv()+1266<-rpisplu_internal()+474<-ktuscu()+294<-kqrcmt()+978<-ktcCommitTxn_new()+5261<-ktcCommitTxn()+94<-kturfptrSlaveWork()+869<-kturfptrSlaveMain()+762<-kxfprdp_int()+1915<-ksbdispatch()+365<-opirip()+522<-opidrv()+581<-sou2o()+165<-opimai_real()+173<-ssthrdmain()+417<-main()+256<-__libc_start_main()+245
(session) sid: 287 ser: 3759 trans: 0x76e67cb0, creator: 0xaf5a2840
flags: (0x41) USR/- flags2: (0x40009) -/-/INC
flags_idl: (0x1) status: BSY/-/-/- kill: -/-/-/-
DID: 0001-0053-000000020000-0000-00000000, short-term DID:
txn branch: (nil)
edition#: 0 user#/name: 0/SYS
oct: 0, prv: 0, sql: 0xc4f3b268, psql: 0xc3e35de0
stats: 0xae2d1810, PX stats: 0x12a12c04
service name: SYS$USERS
client details:
O/S info: user: oracle, term: pts/0, ospid: 47347
machine: zdbm01 program: oracle@zdbm01 (P00V)
Current Wait Stack:
0: waiting for 'cursor: pin S wait on X'
idn=0x4d078f90, value=0x13ac00000000, where=0x500000000
wait_id=22 seq_num=24 snap_id=1
wait times: snap=13.060294 sec, exc=13.060294 sec, total=13.060294 sec
wait times: max=infinite, heur=5 min 11 sec
wait counts: calls=0 os=0
in_wait=1 iflags=0x5a2
There is at least one session blocking this session.
Dumping 1 direct blocker(s):
inst: 1, sid: 5036, ser: 11929
Dumping final blocker:
inst: 1, sid: 5036, ser: 11929
There are 159 sessions blocked by this session.
Dumping one waiter:
inst: 1, sid: 5036, ser: 11929
wait event: 'row cache lock'
p1: 'cache id'=0x3
p2: 'mode'=0x0
min_blocked_time: 0 secs, waiter_cache_ver: 98
Wait State:
fixed_waits=0 flags=0x22 boundary=(nil)/-1
If more than one PROCESS is found this is because you have more than 1 SSD in the same file.
Final Blockers - Current/Previous SQLs
(session) sid: 287 ser: 3759
Current SQL: c4f3b268
ObjectName: Name=update /*+ rule */ undo$ set name=:2,file#=:3,block#=:4,status$=:5,user#=:6,undosqn=:7,xactsqn=:8,scnbas=:9,scnwrp=:10,inst#=:11,ts#=:12,spare1=:13 where us#=:1
FullHashValue=8f7b9f1e491021278dfa3acf4d078f90 Namespace=SQL AREA(00) Type=CURSOR(00) ContainerId=0 ContainerUid=0 Identifier=1292341136 OwnerIdn=0
Statistics: InvalidationCount=0 ExecutionCount=0 LoadCount=2 ActiveLocks=160 TotalLockCount=324 TotalPinCount=37
Previous SQL: c3e35de0
ObjectName: Name=select /*+ rule */ name,file#,block#,status$,user#,undosqn,xactsqn,scnbas,scnwrp,DECODE(inst#,0,NULL,inst#),ts#,spare1 from undo$ where us#=:1
FullHashValue=f9484ec6c26299ad75b4690c15920bf2 Namespace=SQL AREA(00) Type=CURSOR(00) ContainerId=0 ContainerUid=0 Identifier=361892850 OwnerIdn=0
Statistics: InvalidationCount=0 ExecutionCount=176 LoadCount=4 ActiveLocks=160 TotalLockCount=165 TotalPinCount=1
(session) sid: 5036 ser: 11929
Current SQL: c4f3b268
ObjectName: Name=update /*+ rule */ undo$ set name=:2,file#=:3,block#=:4,status$=:5,user#=:6,undosqn=:7,xactsqn=:8,scnbas=:9,scnwrp=:10,inst#=:11,ts#=:12,spare1=:13 where us#=:1
FullHashValue=8f7b9f1e491021278dfa3acf4d078f90 Namespace=SQL AREA(00) Type=CURSOR(00) ContainerId=0 ContainerUid=0 Identifier=1292341136 OwnerIdn=0
Statistics: InvalidationCount=0 ExecutionCount=0 LoadCount=2 ActiveLocks=160 TotalLockCount=324 TotalPinCount=37
Previous SQL: c3e35de0
ObjectName: Name=select /*+ rule */ name,file#,block#,status$,user#,undosqn,xactsqn,scnbas,scnwrp,DECODE(inst#,0,NULL,inst#),ts#,spare1 from undo$ where us#=:1
FullHashValue=f9484ec6c26299ad75b4690c15920bf2 Namespace=SQL AREA(00) Type=CURSOR(00) ContainerId=0 ContainerUid=0 Identifier=361892850 OwnerIdn=0
Statistics: InvalidationCount=0 ExecutionCount=176 LoadCount=4 ActiveLocks=160 TotalLockCount=165 TotalPinCount=1
Mutexes Holders - Current/Previous SQLs
(session) sid: 5036 ser: 11929
Current SQL: c4f3b268
ObjectName: Name=update /*+ rule */ undo$ set name=:2,file#=:3,block#=:4,status$=:5,user#=:6,undosqn=:7,xactsqn=:8,scnbas=:9,scnwrp=:10,inst#=:11,ts#=:12,spare1=:13 where us#=:1
FullHashValue=8f7b9f1e491021278dfa3acf4d078f90 Namespace=SQL AREA(00) Type=CURSOR(00) ContainerId=0 ContainerUid=0 Identifier=1292341136 OwnerIdn=0
Statistics: InvalidationCount=0 ExecutionCount=0 LoadCount=2 ActiveLocks=160 TotalLockCount=324 TotalPinCount=37
Previous SQL: c3e35de0
ObjectName: Name=select /*+ rule */ name,file#,block#,status$,user#,undosqn,xactsqn,scnbas,scnwrp,DECODE(inst#,0,NULL,inst#),ts#,spare1 from undo$ where us#=:1
FullHashValue=f9484ec6c26299ad75b4690c15920bf2 Namespace=SQL AREA(00) Type=CURSOR(00) ContainerId=0 ContainerUid=0 Identifier=361892850 OwnerIdn=0
Statistics: InvalidationCount=0 ExecutionCount=176 LoadCount=4 ActiveLocks=160 TotalLockCount=165 TotalPinCount=1
信息比较多，如果只有ass，自己也可以手动分析，如果大量session在cursor pin等sid 287 ，287等5036, 5036等row cache lock ，
----------------------------------------
SO: 0xabff1228, type: session (4), map: 0xa9420f58
state: LIVE (0x4532), flags: 0x1
owner: 0xafef0be8, proc: 0xafef0be8
link: 0xabff1248[0xc7298d68, 0xafef0c58]
child list count: 26, link: 0xabff1298[0xc7297d68, 0x76fd3020]
pg: 0
SOC: 0xa9420f58, type: session (4), map: 0xabff1228
state: LIVE (0x99fc), flags: INIT (0x1)
(session) sid: 5036 ser: 11929 trans: 0x789674d0, creator: 0xaf58e6b0
flags: (0x41) USR/- flags2: (0x9) -/-/INC
flags_idl: (0x1) status: BSY/-/-/- kill: -/-/-/-
DID: 0001-0035-000000070000-0000-00000000, short-term DID:
txn branch: (nil)
edition#: 0 user#/name: 0/SYS
oct: 6, prv: 0, sql: 0xc4f3b268, psql: 0xc3e35de0
stats: 0xcb452d48, PX stats: 0x12a12c04
service name: SYS$USERS
client details:
O/S info: user: oracle, term: pts/0, ospid: 47286
machine: zdbm01 program: oracle@zdbm01 (P001)
Current Wait Stack:
0: waiting for 'row cache lock'
cache id=0x3, mode=0x0, request=0x3
wait_id=63 seq_num=165 snap_id=51
wait times: snap=0.052141 sec, exc=5 min 4 sec, total=5 min 7 sec
wait times: max=infinite, heur=5 min 7 sec
wait counts: calls=99 os=99
in_wait=1 iflags=0x15a2
There are 159 sessions blocked by this session.
LibraryHandle: Address=0xc4f3b268 Hash=4d078f90 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
ObjectName: Name=update /*+ rule */ undo$ set name=:2,file#=:3,block#=:4,status$=:5,user#=:6,undosqn=:7,xactsqn=:8,scnbas=:9,scnwrp=:10,inst#=:11,ts#=:12,spare1=:13 where us#=:1
根据proc cur调用查call
SOC: 0xb2341840, type: call (3), map: 0xc72981c8
state: LIVE (0x99fc), flags: INIT (0x1)
(call) sess: cur a9425f28, rec a9425f28, usr a9420f58; flg:0 fl2:1; depth:5
svpt(xcb:0x789674d0 sptn:0x2d5 uba: 0x00000000.0000.00 uba: 0x00000000.0000.00)
----------------------------------------
SO: 0xc72a2ec8, type: row cache enqueues (111), map: 0xb3d3b008
state: LIVE (0x4532), flags: 0x0
owner: 0xc72981c8, proc: 0xafef0be8
link: 0xc72a2ee8[0x91ce36c0, 0xc7298238]
pg: 0
SOC: 0xb3d3b008, type: row cache enqueues (111), map: 0xc72a2ec8
state: LIVE (0x99fc), flags: INIT (0x1)
row cache enqueue: count=1 session=0xa9420f58 object=0xcb7e8b50, request=S
flag=03 WAI/TRC/-/-/-/-/-/- savepoint=0x2d7
row cache parent object: addr=0xcb7e8b50 cid=3(dc_rollback_segments) conid=0 conuid=0
hash=fc81f131 typ=21 transaction=0x76e67cb0 flags=0000012a inc=1, pdbinc=1
version=2 mtx version=1152
own=0xcb7e8c20[0xcb77f970,0xcb77f970] wat=0xcb7e8c30[0xb3d3b088,0xb3d3b088] mode=X req=N
status=VALID/UPDATE/-/-/IO/-/-/-/- KGH pinned
--查找0xcb7e8b50
----------------------------------------
SO: 0xc72bb098, type: row cache enqueues (111), map: 0xcb77f8f0
state: LIVE (0x4532), flags: 0x0
owner: 0x789cd770, proc: 0xafef24f8
link: 0xc72bb0b8[0x789cd7e0, 0x789cd7e0]
pg: 0
SOC: 0xcb77f8f0, type: row cache enqueues (111), map: 0xc72bb098
state: LIVE (0x99fc), flags: INIT (0x1)
row cache enqueue: count=1 session=0xad9ea458 object=0xcb7e8b50, mode=X
flag=00 -/-/-/-/-/-/-/- savepoint=0x3
row cache parent object: addr=0xcb7e8b50 cid=3(dc_rollback_segments) conid=0 conuid=0
hash=fc81f131 typ=21 transaction=0x76e67cb0 flags=0000012a inc=1, pdbinc=1
version=2 mtx version=1156
own=0xcb7e8c20[0xcb77f970,0xcb77f970] wat=0xcb7e8c30[0xb3d3b088,0xb3d3b088] mode=X req=N
status=VALID/UPDATE/-/-/IO/-/-/-/- KGH pinned
-- 查找0xad9ea458
----------------------------------------
SO: 0xaff95298, type: session (4), map: 0xad9ea458
state: LIVE (0x4532), flags: 0x1
owner: 0xafef24f8, proc: 0xafef24f8
link: 0xaff952b8[0xc72bb1b8, 0xafef2568]
child list count: 6, link: 0xaff95308[0xc72bae38, 0x76fd4430]
pg: 0
SOC: 0xad9ea458, type: session (4), map: 0xaff95298
state: LIVE (0x99fc), flags: INIT (0x1)
(session) sid: 287 ser: 3759 trans: 0x76e67cb0, creator: 0xaf5a2840
flags: (0x41) USR/- flags2: (0x40009) -/-/INC
flags_idl: (0x1) status: BSY/-/-/- kill: -/-/-/-
DID: 0001-0053-000000020000-0000-00000000, short-term DID:
txn branch: (nil)
edition#: 0 user#/name: 0/SYS
oct: 0, prv: 0, sql: 0xc4f3b268, psql: 0xc3e35de0
stats: 0xae2d1810, PX stats: 0x12a12c04
service name: SYS$USERS
client details:
O/S info: user: oracle, term: pts/0, ospid: 47347
machine: zdbm01 program: oracle@zdbm01 (P00V)
Current Wait Stack:
0: waiting for 'cursor: pin S wait on X'
idn=0x4d078f90, value=0x13ac00000000, where=0x500000000
wait_id=22 seq_num=24 snap_id=1
wait times: snap=13.060294 sec, exc=13.060294 sec, total=13.060294 sec
wait times: max=infinite, heur=5 min 11 sec
wait counts: calls=0 os=0
in_wait=1 iflags=0x5a2
There is at least one session blocking this session.
Dumping 1 direct blocker(s):
inst: 1, sid: 5036, ser: 11929
Dumping final blocker:
inst: 1, sid: 5036, ser: 11929
There are 159 sessions blocked by this session.
Note:
5036 等待row cache lock, 0xcb7e8b50 请求S, 但是该资源被 287 以X 持有，它有在等待cursor pin,等5036, 构成列锁。
此问题比较像Bug 30931981 Open Reset Logs Hangs With ‘row cache lock’ and ‘cursor: pin s wait for x’ Waits，但是不是DC_USER, 包括c函数调用也有出现
ktuscu ==> kernel transaction undo segment row Cache update
kklmsle ==> kernel compile look? m? supplemental logging enabled
which is used to check see if we have supplemental logging enabled on the table. But since this lookup is for a data dictionary object, we should not be having
logging enabled.
还有一个Bug 31747989 中提到的参数 “_min_undosegs_for_parallel_fptr”=0 之前已经调整。
本次安装one-off patch后重启正常。
–enjoy —
微信扫一扫，打赏作者吧～
对不起，这篇文章暂时关闭评论。