ANBOB™

前不久一套oracle 12c RAC环境，客户反馈数据库出现过行锁enq: tx row content和library cache lock。blocker session为dbms_scheduler执行的sql是在收集统计信息，同时db alert log频繁提示qsmqChkOCMV : Timeout while locking object:NNNN, 简单记录.

DB ALERT LOG

2023-09-09T09:10:48.903237+08:00
qsmqChkOCMV : Timeout while locking object:80744
2023-09-09T09:10:49.393017+08:00
qsmqChkOCMV : Timeout while locking object:80744
2023-09-09T09:10:55.771936+08:00
qsmqChkOCMV : Timeout while locking object:80744
2023-09-09T09:11:02.240090+08:00
qsmqChkOCMV : Timeout while locking object:80744
2023-09-09T09:11:11.869999+08:00
Auto-tuning: Shutting down background process GTX1
2023-09-09T09:11:24.071108+08:00
KILL SESSION for sid=(1497, 40663):
Reason = alter system kill session
Mode = KILL HARD SAFE -/-/-
Requestor = USER (orapid = 1289, ospid = 7144498, inst = 2)
Owner = Process: USER (orapid = 1631, ospid = 49807694)
Result = ORA-31
2023-09-09T09:11:25.565394+08:00
qsmqChkOCMV : Timeout while locking object:80744
2023-09-09T09:11:31.223970+08:00
qsmqChkOCMV : Timeout while locking object:80744
2023-09-09T09:11:57.781695+08:00
qsmqChkOCMV : Timeout while locking object:80744
2023-09-09T09:11:58.961708+08:00
qsmqChkOCMV : Timeout while locking object:80744
2023-09-09T09:12:02.509237+08:00
qsmqChkOCMV : Timeout while locking object:80744

Note：
日志中显示qsmqChkOCMV : Timeout while locking ，报错与客户反馈的-ORA-4021的时间点匹配。 提示的数据库对像object_id为80744。

qsmqChkOCMV –》》- query system management dictionary access check on commit mview

DIA trace file

Slave ID: 2, Job ID: 0
----------------------------------------
SO: 0x7000103235cc1f8, type: 4, owner: 0x700010382b2df50, flag: INIT/-/-/-/0x00 if: 0x3 c: 0x3
proc=0x700010382b2df50, name=session, file=ksu.h LINE:15737 ID:, pg=0, conuid=0
(session) sid: 5576 ser: 14916 trans: 0x0, creator: 0x700010382b2df50
flags: (0x210041) USR/- flags2: (0x40009) -/-/INC
flags_idl: (0x1) status: BSY/-/-/- kill: -/-/-/-
0002-0074-0002B2050002-0074-0002B206 DID: , short-term DID:
txn branch: 0x0
edition#: 133 user#/name: 161/ZHIYDBA
oct: 2, prv: 0, sql: 0x700010092013600, psql: 0x700010092013600
stats: 0x700010078d3b370, PX stats: 0x11284bf64
service name: SYS$USERS
client details:
O/S info: user: oracle, term: UNKNOWN, ospid: 65012458
machine: anbob2 program: oracle@anbob2 (J002)
Current Wait Stack:
0: waiting for 'single-task message'
=0x0, =0x0, =0x0
wait_id=158 seq_num=168 snap_id=1
wait times: snap=96962 min 37 sec, exc=96962 min 37 sec, total=96962 min 37 sec
wait times: max=infinite, heur=96962 min 37 sec
wait counts: calls=0 os=0
in_wait=1 iflags=0x5a0
There are 1 sessions blocked by this session.
Dumping one waiter:
inst: 2, sid: 2787, ser: 43602
wait event: 'library cache lock'
p1: 'handle address'=0x70001007e84be20
p2: 'lock address'=0x70001003a62e828
p3: '100*mode+namespace'=0x13b6800010003
row_wait_obj#: 4294967295, block#: 0, row#: 0, file# 0
min_blocked_time: 886 secs, waiter_cache_ver: 18776
Wait State:
fixed_waits=0 flags=0x22 boundary=0x0/-1
Session Wait History:
elapsed time of 0.000784 sec since current wait
0: waited for 'db file sequential read'
file#=0x1, block#=0x871, blocks=0x1



Dumping process info of pid[116.65012458] requested by pid[1018.56426816]
Dumping process 116.65012458 info:

*** 2023-09-09T08:46:51.814892+08:00
Process diagnostic dump for oracle@anbob2 (J002), OS id=65012458,
pid: 116, proc_ser: 231, sid: 5576, sess_ser: 14916
-------------------------------------------------------------------------------
os thread scheduling delay history: (sampling every 1.000000 secs)
0.000000 secs at [ 08:46:51 ]
NOTE: scheduling delay has not been sampled for 0.191027 secs
0.000000 secs from [ 08:46:47 - 08:46:52 ], 5 sec avg
0.000000 secs from [ 08:45:52 - 08:46:52 ], 1 min avg
0.000000 secs from [ 08:41:52 - 08:46:52 ], 5 min avg
loadavg : 12.83 12.06 11.85
swap info: free_mem = 244902.54M rsv = 64.00M
alloc = 587.68M avail = 16384.00M swap_free = 15796.32M
F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME CMD
240001 A oracle 65012458 1 0 60 20 cb104f590 423988 f10010004cf060c8 Jul 04 - 0:00 ora_j002_HISDB2
Short stack dump:
ksedsts()+432<-ksdxfstk()+68<-ksdxcb()+892<-sspuser()+220<-__sighandler()<-read()+776<-nttrd()+288<-nsprecv()+620<-nscon()+392<-IPRA.$IPRA.$nsdo()+24736<-nsdo()+196<-nsbasic_rc()+48<-nsre
cv()+152<-nscall3()+276<-nscall()+3624<-niotns()+15700<-nigcall()+80<-osncon()+1036<-kpkiadef()+1000<-upiini()+832<-upiah0()+116<-kpuatch()+1396<-OCIServerAttach()+172<-kpnconn()+784<-npi
con0()+1248<-kpndbcon()+328<-OCIKDBLinkConn2()+112<-OCIKDBLinkConn()+100<-ddfnet2Normal()+304<-IPRA.$kkmfcbrm()+224<-kkmpfcbk()+2588<-qcsprfro()+604<-IPRA.$qcsprfro_tree()+304<-IPRA.$qcsp
rfro_tree()+1984<-qcspafq()+312<-IPRA.$qcspqbDescendents()+280<-qcspqb()+244<-kkmdrv()+84<-IPRA.$opiSem()+1920<-opiDeferredSem()+428<-opitca()+484<-kksFullTypeCheck()+84<-rpiswu2()+580<-k
ksLoadChild()+5728<-kxsGetRuntimeLock()+1684<-kksfbc()+14652<-kkspbd0()+764<-kksParseCursor()+720<-opiosq0()+2556<-opipls()+13776<-opiodr()+1248<-rpidrus()+204<-skgmstack()+116<-rpidru()+
152<-rpiswu2()+580<-rpidrv()+1080<-IPRA.$psddr0()+424<-psdnal()+660<-pevm_EXECC()+304<-pfrinstr_EXECC()+108<-IPRA.$pfrrun_no_tool()+92<-pfrrun()+1108<-plsql_run()+800<-peicnt()+324<-kkxex
e()+684<-opiexe()+23160<-opiodr()+1248<-rpidrus()+204<-skgmstack()+116<-rpidru()+152<-rpiswu2()+580<-rpidrv()+1080<-rpiexe()+108<-kkjex1e()+6624<-kkjex1e_cdb()+376<-IPRA.$kkjsexe()+1388<-
kkjrdp()+684<-opirip()+964<-opidrv()+556<-sou2o()+184<-opimai_real()+240<-ssthrdmain()+460<-main()+208<-__start()+112

-------------------------------------------------------------------------------

Slave ID: 2, Job ID: 0
----------------------------------------
SO: 0x7000103235cc1f8, type: 4, owner: 0x700010382b2df50, flag: INIT/-/-/-/0x00 if: 0x3 c: 0x3
proc=0x700010382b2df50, name=session, file=ksu.h LINE:15737 ID:, pg=0, conuid=0
(session) sid: 5576 ser: 14916 trans: 0x0, creator: 0x700010382b2df50
flags: (0x210041) USR/- flags2: (0x40009) -/-/INC
flags_idl: (0x1) status: BSY/-/-/- kill: -/-/-/-
0002-0074-0002B2050002-0074-0002B206 DID: , short-term DID:
txn branch: 0x0
edition#: 133 user#/name: 161/ZHIYDBA
oct: 2, prv: 0, sql: 0x700010092013600, psql: 0x700010092013600
stats: 0x700010078d3b370, PX stats: 0x11284bf64
service name: SYS$USERS
client details:
O/S info: user: oracle, term: UNKNOWN, ospid: 65012458
machine: anbob2 program: oracle@anbob2 (J002)
Current Wait Stack:
0: waiting for 'single-task message'
=0x0, =0x0, =0x0
wait_id=158 seq_num=168 snap_id=1
wait times: snap=96962 min 37 sec, exc=96962 min 37 sec, total=96962 min 37 sec
wait times: max=infinite, heur=96962 min 37 sec
wait counts: calls=0 os=0
in_wait=1 iflags=0x5a0
There are 1 sessions blocked by this session.
Dumping one waiter:
inst: 2, sid: 2787, ser: 43602
wait event: 'library cache lock'
p1: 'handle address'=0x70001007e84be20
p2: 'lock address'=0x70001003a62e828
p3: '100*mode+namespace'=0x13b6800010003
row_wait_obj#: 4294967295, block#: 0, row#: 0, file# 0
min_blocked_time: 886 secs, waiter_cache_ver: 18776
Wait State:
fixed_waits=0 flags=0x22 boundary=0x0/-1
Session Wait History:
elapsed time of 0.000784 sec since current wait
0: waited for 'db file sequential read'
file#=0x1, block#=0x871, blocks=0x1
wait_id=157 seq_num=167 snap_id=1
wait times: snap=0.000745 sec, exc=0.000745 sec, total=0.000745 sec



----------------------------------------
SO: 0x700010094830bf8, type: 110, owner: 0x700010021a6edb8, flag: INIT/-/-/-/0x00 if: 0x3 c: 0x3
proc=0x700010382b2df50, name=LIBRARY OBJECT PIN, file=kgl.h LINE:9859 ID:, pg=0, conuid=0

LibraryObjectPin: Address=700010094830bf8 Handle=70001007e84be20 Mode=S Lock=700010099722c88 ClusterLock=70001034bbbae40
User=7000103235cc1f8 Session=7000103235cc1f8 Count=1 Mask=0701 Flags=[100] SavepointNum=0x153
LibraryHandle: Address=70001007e84be20 Hash=17770ebc LockMode=S PinMode=S LoadLockMode=0 Status=VALD
ObjectName: Name=INPSICK.SICK_SETTLE_MASTER
FullHashValue=eb820a721668db92c530145e17770ebc Namespace=TABLE/PROCEDURE(01) Type=TABLE(02) ContainerId=0 ContainerUid=0 Identifier=80744 OwnerIdn=146
Statistics: InvalidationCount=0 ExecutionCount=0 LoadCount=3322 ActiveLocks=1 TotalLockCount=2170111 TotalPinCount=2284531
Counters: BrokenCount=29 RevocablePointer=1 KeepDependency=0 Version=0 BucketInUse=2365782 HandleInUse=2365782 HandleReferenceCount=0
Concurrency: DependencyMutex=70001007e84bed0(0, 1039766, 0, 0) Mutex=70001007e84bf70(0, 25326065, 325, 0)
Flags=PIN/TIM/[00002801] Flags2=[0000]
WaitersLists:
Lock=70001007e84beb0[70001003a62e8a8,70001082c626158]
Pin=70001007e84be90[70001007e84be90,70001007e84be90]
LoadLock=70001007e84bf08[70001007e84bf08,70001007e84bf08]
Timestamp: Current=12-28-2022 12:19:45
HandleReference: Address=70001007e84c020 Handle=70001011f75d1e8 Flags=OWN[200]
LockInstance: id='LBeb820a721668db92' GlobalEnqueue=0 ReleaseCount=0
PinInstance: id='NBeb820a721668db92' GlobalEnqueue=0
LibraryObject: Address=70001007e83f2e8 HeapMask=0000-0741-074d-0000 Flags=EXS/LOC[0004] Flags2=[4000000] PublicFlags=[0000]
DataBlocks:
Block: #='0' name=KGLH0^17770ebc pins=0 Change=NONE
Heap=70001007e840278 Pointer=70001007e83f3b8 Extent=70001007e83f240 Flags=I/-/P/A/-/-/-
FreedLocation=0 Alloc=18.023438 Size=19.882812 LoadTime=87934807851
Block: #='2' name=PLDIA^17770ebc pins=0 Change=NONE
Heap=70001007896ead8 Pointer=0 Extent=0 Flags=I/-/-/-/-/-/-
FreedLocation=3 Alloc=0.000000 Size=0.000000 LoadTime=0
Block: #='3' name=KKBTD^17770ebc pins=0 Change=NONE
Heap=70001007e83fc68 Pointer=0 Extent=0 Flags=I/-/-/-/-/-/-
FreedLocation=3 Alloc=0.000000 Size=0.000000 LoadTime=0
Block: #='8' name=KGLS^17770ebc pins=1 Change=NONE
Heap=70001007e83f680 Pointer=700010bf606a5a8 Extent=700010bf60698c8 Flags=I/-/P/A/-/-/-
FreedLocation=0 Alloc=52.906250 Size=60.000000 LoadTime=92244537915
Block: #='9' name=KGLS^17770ebc pins=1 Change=NONE
Heap=70001007e83fab8 Pointer=700010bf71c4dd0 Extent=700010bf71c3fa0 Flags=I/-/P/A/-/-/-
FreedLocation=0 Alloc=0.687500 Size=4.000000 LoadTime=92244537920
Block: #='10' name=KGLS^17770ebc pins=1 Change=NONE
Heap=70001007e83fb90 Pointer=700010be9f62370 Extent=700010be9f61460 Flags=I/-/P/A/-/-/-
FreedLocation=0 Alloc=2.406250 Siz


*** 2023-09-09T08:46:51.895825+08:00
----------------------------------------
SO: 0x700010382b2df50, type: 2, owner: 0x0, flag: INIT/-/-/-/0x00 if: 0x3 c: 0x3
proc=0x700010382b2df50, name=process, file=ksu.h LINE:15729 ID:, pg=0, conuid=0
(process) Oracle pid:116, ser:231, calls cur/top: 0x700010021a6edb8/0x7000100a677aec8
flags : (0x0) - icon_uid:0 logon_pdbid=0
flags2: (0x10), flags3: (0x10)
call error: 0, sess error: 0, txn error 0
intr queue: empty
(post info) last post received: 0 0 112
last post received-location: kji.h LINE:5274 ID:kjata: wake up enqueue owner
last process to post me: 0x7000103a2b1f4e8 1 6
last post sent: 0 0 32
last post sent-location: ksa2.h LINE:291 ID:ksasnd
last process posted by me: 0x700010322b057a8 1 6
waiter on post event: 0
(latch info) hold_bits=0x0 ud_influx=0x22e
Process Group: DEFAULT, pseudo proc: 0x700010302df61f8
O/S info: user: oracle, term: UNKNOWN, ospid: 65012458
OSD pid info:
KGL-UOL (Process state object)
KGX Atomic Operation Log 700010382b2ec40
Mutex 0(0, 0) idn 0 oper NONE(0)
FSO mutex uid 65534 efd 0 whr 0 slp 0
KGX Atomic Operation Log 700010382b2eca8
Mutex 0(0, 0) idn 0 oper NONE(0)
FSO mutex uid 65534 efd 0 whr 0 slp 0
KGX Atomic Operation Log 700010382b2ed10
Mutex 0(0, 0) idn 0 oper NONE(0)
FSO mutex uid 65534 efd 0 whr 0 slp 0
KGX Atomic Operation Log 700010382b2ed78
Mutex 0(0, 0) idn 0 oper NONE(0)
FSO mutex uid 65534 efd 0 whr 0 slp 0
KGX Atomic Operation Log 700010382b2ede0
Mutex 0(0, 0) idn 0 oper NONE(0)


Slave ID: 2, Job ID: 0
----------------------------------------
SO: 0x7000103235cc1f8, type: 4, owner: 0x700010382b2df50, flag: INIT/-/-/-/0x00 if: 0x3 c: 0x3
proc=0x700010382b2df50, name=session, file=ksu.h LINE:15737 ID:, pg=0, conuid=0
(session) sid: 5576 ser: 14916 trans: 0x0, creator: 0x700010382b2df50
flags: (0x210041) USR/- flags2: (0x40009) -/-/INC
flags_idl: (0x1) status: BSY/-/-/- kill: -/-/-/-
0002-0074-0002B2050002-0074-0002B206 DID: , short-term DID:
txn branch: 0x0
edition#: 133 user#/name: 161/ZHIYDBA
oct: 2, prv: 0, sql: 0x700010092013600, psql: 0x700010092013600
stats: 0x700010078d3b370, PX stats: 0x11284bf64
service name: SYS$USERS
client details:
O/S info: user: oracle, term: UNKNOWN, ospid: 65012458
machine: anbob2 program: oracle@anbob2 (J002)
Current Wait Stack:
0: waiting for 'single-task message'
=0x0, =0x0, =0x0
wait_id=158 seq_num=168 snap_id=1
wait times: snap=96962 min 37 sec, exc=96962 min 37 sec, total=96962 min 37 sec
wait times: max=infinite, heur=96962 min 37 sec
wait counts: calls=0 os=0
in_wait=1 iflags=0x5a0
There are 1 sessions blocked by this session.
Dumping one waiter:
inst: 2, sid: 2787, ser: 43602
wait event: 'library cache lock'
p1: 'handle address'=0x70001007e84be20
p2: 'lock address'=0x70001003a62e828
p3: '100*mode+namespace'=0x13b6800010003
row_wait_obj#: 4294967295, block#: 0, row#: 0, file# 0
min_blocked_time: 886 secs, waiter_cache_ver: 18776
Wait State:
fixed_waits=0 flags=0x22 boundary=0x0/-1
Session Wait History:
elapsed time of 0.000784 sec since current wait
0: waited for 'db file sequential read'
file#=0x1, block#=0x871, blocks=0x1
wait_id=157 seq_num=167 snap_id=1
wait times: snap=0.000745 sec, exc=0.000745 sec, total=0.000745 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000014 sec of elapsed time
1: waited for 'gc cr grant 2-way'

原因:
会话A更新一个表，该表是mview的主表
会话 B 正在运行 DBMS_STATS.GATHER_TABLE_STATS 命令。 它在X模式下获得了同一张表的行缓存锁，同时将列统计信息存储到字典中。
会话 A 执行 COMMIT。
在 COMMIT 发生之前，会话 A 需要验证它是否已更新任何作为 on-commit mview 的主表的表。 无论现有 mview 是按需刷新还是提交时刷新，都会发生此检查。 在此检查期间，它将尝试以 S 模式 NOWAIT 锁定该表的行缓存和库缓存锁。 该请求将会失败，因为会话 B 已经持有 X 模式的锁。
会话 A 将在“等待表锁”事件处等待 3 秒，并重试尝试在 S 模式 NOWAIT 下获取锁，最多 10 次。
如果会话 B 超过 30 秒没有释放 X 锁，会话 A 的所有尝试都将失败，并且会话 A 将收到 ORA-4021 错误。

解决方法
某些操作可能会与优化器统计信息收集产生冲突，特别是当目标表大小较大或表中存在大量分区时。在这种情况下，建议更改运行自动统计信息收集的维护窗口，或者避免与用户 DML 同时收集统计信息，以避免这些操作可能导致的潜在冲突。如果不想更改统计信息收集时间，但又需要防止提交期间出现 ORA-4021 错误，则减少遇到此错误机会的另一种方法是暂时锁定目标表的统计信息。此错误已在 19.11 及更高版本中通过修复 bug 30751171 得到修复，注意默认安装补丁后默认并未启用，需要手动启用：

conn / as sysdba
alter system set "_fix_control"='30751171:ON';

这里我们选择了锁定对象的统计信息，手动闲时job更新。

打赏

微信扫一扫，打赏作者吧～