并行insert出现library cache lock与cursor: pin S wait on X等待问题记录

一、故障现象与紧急处理

开发反馈凌晨5点左右应用出现大量报错 ORA-04021: timeout occurred while waiting to lock object，并且集中出现在insert im_message这个表的操作上，其他表不受影响。

查看当时等待情况，发现确实有异常的内存等待，而且还可以看到sid=15和1347的会话在相互等待，串成了环。

SQL> select sid,status,blocking_session,final_blocking_session,event,p1 from v$session where blocking_session is not null;

SID STATUS BLOCKING_SESSION FINAL_BLOCKING_SESSION
---------- -------- ---------------- ----------------------
EVENT P1
---------------------------------------------------------------- ----------
15 ACTIVE 1347 1347
row cache lock 2

783 ACTIVE 785 1347
cursor: pin S wait on X 2660772620

785 ACTIVE 1347 1347
library cache lock 2154287504

查看各会话信息

SQL> select sid,sql_id,machine,program,osuser from v$session where sid=15;

SID SQL_ID
---------- -------------
MACHINE
----------------------------------------------------------------
PROGRAM
------------------------------------------------
OSUSER
--------------------------------------------------------------------------------
15 aasrjxdzj2kh4
IM-DB-P02
oracle@IM-DB-P02 (P001)
oracle

SQL> select sid,sql_id,machine,program,osuser from v$session where sid=1347;

SID SQL_ID
---------- -------------
MACHINE
----------------------------------------------------------------
PROGRAM
------------------------------------------------
OSUSER
--------------------------------------------------------------------------------
1347 aasrjxdzj2kh4
IM-DB-P02
oracle@IM-DB-P02 (J000)
oracle

SQL> select distinct sql_text from v$sql where sql_id='aasrjxdzj2kh4';

SQL_TEXT
--------------------------------------------------------------------------------
alter table IM_MESSAGE MOVE SUBPARTITION SYS_SUBP357943 TABLES
PACE DATA_WARM online PARALLEL (DEGREE 2)

aasrjxdzj2kh4 这个sql是我们设置的定时任务，每天5点左右执行，符合故障发生的时间点和表名。不过已经正常执行了半年以上，猜测可能遇到了bug。

SQL> select sid,sql_id,machine,program,osuser from v$session where sid=783;

SID SQL_ID
---------- -------------
MACHINE
----------------------------------------------------------------
PROGRAM
------------------------------------------------
OSUSER
--------------------------------------------------------------------------------
783 7sy9652g9hasc
imsecurity-prod
JDBC Thin Client
im

SQL> select distinct sql_text from v$sql where sql_id='7sy9652g9hasc';

SQL_TEXT
--------------------------------------------------------------------------------
insert into IM_MESSAGE (...) values ( :1 , :2 , :3 , :4 , :5 , :
6 , :7 , :8 , :9 , :10 )

7sy9652g9hasc 这个就是业务的insert语句，至此可以确定是被job阻塞了，于是我们临时kill掉job执行会话，即 sid=15。

SQL> select sid,SERIAL#,status,p1 from v$session where sid=15;

SID SERIAL# STATUS P1
---------- ---------- -------- ----------
15 24035 ACTIVE 2

SQL> alter system kill session '15,24035' immediate;

System altered.

SQL> select sid,status,blocking_session,final_blocking_session,event,p1 from v$session where blocking_session is not null;

no rows selected

kill完后数据库没有了等待，业务也反馈已恢复正常。

虽然问题暂时解决了，还是需要更进一步分析，找到根因，避免再次发生。保留ash，留待上班时间分析。

create table ash0717 as select * from v$active_session_history a;

二、查看alert日志

alert日志中也看到了1347与15两个会话的异常信息，这个报错代表了什么？

2021-07-17T05:00:29.469934+08:00
ARC2 (PID:20173): Archived Log entry 50268 added for T-1.S-71818 ID 0x6523b129 LAD:1
2021-07-17T05:05:28.875332+08:00
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=40
System State dumped to trace file /data/prd/oracle/database/diag/rdbms/imdb/imdb/trace/imdb_p001_108321.trc

trace记录
40: P001 ospid 108321 sid 15 ser 24035, waiting for 'row cache lock'
Cmd: CREATE TABLE
Blocked by inst: 1, sid: 1347, ser: 38289
Final Blocker inst: 1, sid: 1347, ser: 38289

79: J000 ospid 87205 sid 1347 ser 38289, waiting for 'PX Deq: Execute Reply'
Cmd: CREATE TABLE
Blocked by inst: 1, sid: 15, ser: 24035
Final Blocker inst: 1, sid: 15, ser: 24035

同时日志里记录了stack

*** 2021-07-17T05:05:37.821389+08:00
PROCESS 40: P001
----------------------------------------
Short stack dump:
ksedsts()+426<-ksdxfstk()+58<-ksdxdocmdmultex()+6036<-ksdxdocmdmult()+55<-ksudmp_proc()+1628<-ksudss_main()+1976<-ksudss_opt()+1544<-kqrget()+4131<-kqrLockPo()+246<-kqrpre2()+1117<-kqrpre()+35<-ktsxs_add()+531<-ktsla_alloc_extent()+1949<-ktsla_extent_allocate()+84<-ktrsexec()+424<-ktsla_alloc_space1()+499<-ktsldfsp_main()+1575<-ktslfsp()+607<-kdliPurgeCache()+8835<-kdliccCbk()+5451<-ktcccDeleteCommitCallbacks()+439<-ktcccdel()+46<-ktpPrepareSlaveTxn()+1191<-kxfxspt()+90<-kxfxmai()+2565<-kxfprdp_int()+1915<-ksbdispatch()+367<-opirip()+522<-opidrv()+581<-sou2o()+165<-opimai_real()+173<-ssthrdmain()+417<-main()+256<-__libc_start_main()+245

三、异常等待分析

sid 783（业务insert，等待cursor: pin S wait on X） -> 785（业务insert，等待library cache lock） -> 1347（move 分区job，等待PX Deq: Execute Reply） -> 15 （move 分区job并行进程，等待 row cache lock）-> 1347

这里最奇怪的依然是1347与15两个会话，明明相互等待，为什么没有产生死锁报错。另外我们依次三个异常的内存等待

row cache lock
library cache lock
cursor: pin S wait on X

1. row cache lock

row cache lock是对共享内存（Shared pool）中数据字典信息（dc_XXX）进行操作时，加载的锁（Enqueue ）。可以通过v$rowcache和v$session的p1字段，查询是在等待哪个数据字典信息。

例如：15会话 p1=2,p2=0,p3=3

select type,parameter from v$rowcache where cache#=2;
-- 返回
PARENT    dc_segments

DC_SEGMENTS：该行缓冲队列锁会在段分配的时候发生，需要观察持有这个队列锁的会话在做什么。

因此，15想读取dc_segments，但被1347阻塞；1347执行move，持有dc_segments字典锁

783 -> 785 -> 1347 -> 15 （等段分配）-> 1347

当某进程不能够立即获得row cache lock时，会进行等待；并且每隔3秒钟会进行一次Check，看看是否能获得请求的锁；如果超过1000次（50分钟）的Check还没有获得row cache lock，就会在警告日志中输出下列信息

并且通常会输出相关的日志文件（包含SYSTEM STATE信息）

如果多个进程间发生了死锁，也可能发生WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! 等待。但是，row cache lock没有自动检测死锁机制，不会像ORA-60（Enqueue ）、ORA-4020/ORA-4021（Library cache lock）一样报出错误信息和自动解除死锁。所以，当发生WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! 等待死锁时，需要alter system kill session或者OS 命令手动地杀死持有row cache lock的进程以解除死锁。

一般来讲，警告日志（alert log）中出现”WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! “等待信息时，会伴随着数据库挂起或变慢，而其原因很有可能是Oracle数据库的Bug引起的。

另外，数据库的配置或者应用不当时，也可能发生同样的问题。

例如：

SGA/共享池的配置不当：由于SGA/共享池过小，导致SGA/共享池频繁地进行大小调整的操作（resize）时，获得各种latch阻塞其他进程，从而引起"WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! "等待发生。
SQL应用对某类型的ROW CACHE访问过于频繁发生竞争等。

参考

row cache lock_ITPUB博客

"WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! "等待原理概述 - 博客 - 编程圈

https://www.cnblogs.com/nathon-wang/p/10674531.html

Bug 32148419 - High Row Cache Lock Waits on Alter Table Exchange Partition in Rac Environment (Doc ID 32148419.8)
High Library Cache Lock and Library Cache Load Lock Waits During Concurrent Heavy Mixed PMOPs and DML on Several Partitioned Tables (Doc ID 2181034.1)
Bug 30489582 - Row Cache Lock Blocker/Deadlock Detection Does Not Work in RAC (Doc ID 30489582.8)
Bug 7416901 - Deadlock between QC and PQ slaves when CELL_PARTITION_LARGE_EXTENTS = ALWAYS (Doc ID 7416901.8)

WAITEVENT: "row cache lock" Reference Note (Doc ID 34609.1)
Troubleshooting: "WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! " (Doc ID 278316.1)

2. library cache lock 等待

A library cache lock controls the concurrency between sessions accessing an object in the library cache by acquiring a lock on the object handle. A library cache lock may is be requested when locating an object in the library cache.

当一个session对SQL语句进行硬解析的时候，这个session就必须获得library cache lock，这样其他session就不能够访问或者更改这个SQL所引用的对象。如果这个等待事件花了很长时间，通常表明共享池太小（由于共享池太小，需要搜索free的chunk，或者将某些可以被移出的object page out，这样要花很长时间）。当然，也有可能另外的session正在对object进行修改，比如split 分区等，而当前session需要引用那个table，那么这种情况下我们必须等另外的session进行完毕。

Library cacheHandle 里保存了lock 和 pin的信息。而且在Library cache handle和child cursor上都有lock 和pin。它们称为library cache lock和library cache pin。它们是用来控制对library cache object的并发访问的。Lock管理并发，pin管理一致性，lock是针对于library cache handle,而pin是针对于heap。
当我们想要访问某个library cache object，首先要获得这个指向这个object的handle的lock，获得这个lock之后我们就需要pin住指向这个object的heap。

Library Cache lock有3中模式：

（1）Share(S)：当读取一个library cache object的时候获得

（2）Exclusive(X)：当创建/修改一个library cache object的时候获得

（3）Null(N)：用来确保对象依赖性

比如一个进程想要编译某个视图，就会获得一个共享锁，如果要create/drop/alter某个对象，就会获得exclusive lock。Null锁非常特殊，我们在任何可以执行的对象(cursor，function)上面都拥有NULL锁，我们可以随时打破这个NULL锁，当这个NULL锁被打破了，就表示这个对象被更改了，需要重新编译。

NULL锁主要的目的就是标记某个对象是否有效。比如一个SQL语句在解析的时候获得了NULL 锁，如果这个SQL的对象一直在共享池中，那么这个NULL锁就会一直存在下去，当这个SQL语句所引用的表被修改之后，这个NULL锁就被打破了，因为修改这个SQL语句的时候会获得Exclusive 锁，由于NULL锁被打破了，下次执行这个SQL的时候就需要重新编译。

可能发生library cache pin和library cache lock的情况：

在存储过程或者函数正在运行时被编译。
在存储过程或者函数正在运行时被对它们进行授权、或者移除权限等操作。
对某个表执行DDL期间，有另外的会话对该表执行DML或者DDL。
PL/SQL对象之间存在复杂的依赖性

每个想使用或修改已经locked/pin的对象的SQL语句，将会等待事件'library cache pin'或'library cache lock'直到超时。超时通常发生在5分钟后，然后SQL语句会出现ORA-4021的错误。如果发现死锁，则会出现ORA-4020错误。

回到我们的故障：

alter table语句（1347会话）以X模式持有library cache lock，又因为自己被阻塞没有及时释放library cache lock，导致业务insert语句（785会话）被阻塞，当阻塞超过5分钟后，业务遇到超时报错ORA-4021。

参考

https://blog.csdn.net/tianlesoftware/article/details/7956996
https://www.cndba.cn/Dave/article/1381
https://blog.csdn.net/tianlesoftware/article/details/6560956
https://www.modb.pro/db/33371
https://www.cndba.cn/Dave/article/1378
https://www.cnblogs.com/hllnj2008/p/4788066.html

https://blog.csdn.net/su377486/article/details/48816411

41.Oracle深度学习笔记——shared_pool底层知识大集合【图文】_mb611a2e88042f6_51CTO博客

http://t.askmaclean.com/thread-4842-1-1.html
https://www.cndba.cn/Dave/article/502

WAITEVENT: "library cache lock" Reference Note (Doc ID 34578.1)
How to Find which Session is Holding a Particular Library Cache Lock (Doc ID 122793.1)

3. cursor: pin S wait on X等待

前面说到

Library Cache lock有3中模式：

Share(S)：当读取一个library cache object的时候获得
Exclusive(X)：当创建/修改一个library cache object的时候获得
Null(N)：用来确保对象依赖性

而 Library Cache pin有2种模式：

Share(S)：读取
object heap Exclusive(X)：修改object heap

所以这里的cursor pin S wait on X 就是读（pin S）在等待修改（pin X）的情况，那么这说明了肯定有相同的sql在同时执行，不然只有cursor pin S 或者cursor pin X。

11g开始Library Cache pin改名叫mutex，所以这个等待也可以说成：某个会话需要申请S模式的mutex，而mutex被其他会话以X模式占有了。

从v$ash中可以看到，783会话的正在解析阶段，但被785阻塞，并且它们也是相同的sql。

参考

FAQ: 'cursor: mutex ..' / 'cursor: pin ..' / 'library cache: mutex ..' Type Wait Events (Doc ID 1356828.1)
Troubleshooting 'cursor: pin S wait on X' waits. (Doc ID 1349387.1)
Troubleshooting: Waits for Mutex Type Events (Doc ID 1377998.1)
https://blog.csdn.net/tianlesoftware/article/details/6549018

三、分析结论与解决方案

1347与15进程因为bug（比较遗憾没有搜索到类似bug）出现死锁，但检测不到，1347在等待15执行完返回结果，而15在等待1347执行完释放数据字典资源。1347长期以X模式占据内存资源造成业务insert语句785会话出现 library cache lock 等待，进而造成783会话出现cursor: pin S wait on X等待。

虽然bug没有找到，但明显1347与15是与并行有关的，修改语句为不使用并行后问题未再发生。并且由于每次move的是子分区，数据量不大，速度完全可以接受。

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

类似等待案例 https://blog.csdn.net/Hehuyi_In/article/details/108199880

问题会话 cursor: pin S wait on X -> 2 library cache lock -> 1129 row cache lock -> 951 log file sequential read -> Wnnn后台进程