前言
cursor: pin S wait on X是我们日常经常会遇到的SQL解析相关的等待事件，一般持续时间不长。如果不是业务响应特别敏感的系统，偶发的等待可能会被忽略。
但是如果是敏感度特别高的系统，而阻塞时间又高达分钟级，领导本身就是DBA出身，简单的原理解释完全无用，一旁虎视眈眈，压力山大啊……
本期分享通过一个实战案例给大家带来如下收获：
1、 cursor: pin S wait on X等待事件的底层原理
2、 如何快速找到会话阻塞源及当时正在执行的操作
3、 如何通过trace工具在复现时抓取足够信息验证问题原因
问题说明
某千亿规模制造业客户DBA打来电话，说近期某核心库连续多次出现短暂会话阻塞，虽然业务部门暂时没有不良反应，但是领导要求分析原因，EM监控出现大量cursor: pin S wait on X阻塞会话：
阻塞持续2分钟左右恢复。
查看历史监控，此事件发生频率较高，需要找到问题原因及解决方案。
数据库环境说明：
Redhat Linux 6_X64
Oracle 11.2.0.4PSU181016 RAC
CPU 96C，内存384GB
确认问题
3.1 什么是cursor: pin S wait on X等待事件？
官方文档说明：
WAITEVENT: "cursor: pin S wait on X" Reference Note (Doc ID 1298015.1)
A session waits for "cursor: pin S wait on X" when it wants a mutex in S (share) mode on a specific cursor but some other session holds that same mutex in X (exclusive) mode. Hence the current session has to wait for the X mode holder to release the mutex.
Mutexes are local to the current instance in RAC environments.
当一个会话以X模式持有某个cursor（如sql/procedure/function/package body等）的mutex时，如果另一个会话需要以S模式请求该cursor的mutex；一般来说，对cursor进行硬解析时，会以X模式持有cursor的mutex，而对cursor进行软解析时，则会以S模式持有cursor的mutex；
举一个简单的例子，一个会话（SESSION_A）正在解析（硬解析）某一个sql语句（SQL_A），当另一个会话（SESSION_B）同时执行这条sql语句（SQL_A）时（执行前需要对该语句进行软解析），SESSION_B就会等待cursor:pin S wait on X 事件。
3.2 ASH记录分析
select * from dba_hist_active_sess_history
where sample_time >to_date('2020-12-08 08:05:00','YYYY-MM-DD HH24:MI:SS') and sample_time <= to_date('2020-12-08 08:07:00','YYYY-MM-DD HH24:MI:SS')
order by sample_time ASC;
可以发现大量会话都在执行SQL b5uaamq0kr456，是一个insert操作，等待cursor:pin S wait on X，阻塞者是5080,22209会话。
下面看看当时5080会话在干什么？
发现执行SQL同样是b5uaamq0kr456，等待事件是 db file sequential read，这个是一个数据单块读的等待，为什么？
看看ash5080当前的sql执行阶段是啥？
ash记录里面的等待事件容易令人迷惑（不要只看等待时间，还需要结合session status和IN_XXX的几个列分析具体在干什么):
(1) 可以发现阻塞的会话都在执行硬解析，具体阻塞会话是5080，显示的SQL_ID是当前执行的sql，对应的sql_child_number是4，这个没问题：
(2) 这里虽然看到虽然等待事件是db file sequential read,但是实际SQL在做硬解析(IN_HARD_PARSE)，另外解析的SQL child number是3，和被阻塞的会话申请的子游标是不同的！
看到这里，我们又会产生2个疑问：
(1)为什么这个SQL会产生硬解析？
(2)硬解析时间为什么会持续这么长(2分钟)?
有经验的同学，可能想到一些可能的原因了，比如：
(1) shared pool内存不足，出现动态resize？
(2) 大表没有统计信息，出现动态采样？
(3) sql游标高版本？
……
下面尝试分析各类信息进行解答：
3.3 SQL为什么会产生硬解析
先看sql是什么(sqlhc报告)：
是一个非常简单的INSERT语句，也只发现2个子游标，没有发现动态采样等信息。
从version_rpt高版本分析结果看，这个sql没有当前明显的高版本：
查看对应的表的定义，是一个RANGE一级分区表(分区数接近1w)，含一个BLOB字段：
检查对应时点的AWR报告：
本数据库shared pool设置为20GB：
但是awr报告可以看到实际占有已经到了接近30GB：
在awr看看SGA内存的分配情况：
主要的大块内存占用情况如下：
1、 gcs resources/shawdows(4.7G)：GCS资源信息
2、 KGLH0(2.6G): SQL heap0内存
3、 SQLA(5.7G)：sql游标内存
4、kglsim heap/object batch(2.7G)：library cache ADVISOR内存
5、 PRTMV(1.3G)
其中2、3都和游标数量直接关联，分析系统常量SQL情况：
发现大量使用常量的SQL，最高版本数量达6W+，这些sql会占据大量library cache及频繁硬解析！
而对应library cache advisor, 通过分配内存来模拟需要多大的LIBRARY CACHE可以达到什么效果。这个功能意义不大，可以直接关闭：
alter system set "_library_cache_advice"=FALSE;
另外本机开启了NUMA功能，也建议在主机/OS层面关闭已消除可能的内存碎片问题。
PRTMV内存的大量占用是因为有些含大量分区的表(如：DCCONTEXT)经常通过split操作导致的BUG：
Bug 20635353 - High PRTMV Memory Allocations when Inserting into Partitioned Tables Simultaneously with Partition Maintenance Operations (Doc ID 20635353.8)
但是没有本库对应版本的补丁，需要升级到PSU200714再打，而且11g已经停止支持，需要extended support才能下载补丁：
从上面分析可以看出，大量常量SQL及library cache advisor及NUMA等会导致shared pool内存紧张，游标被aged out是导致硬解析的一个重要原因。
另外通过统计表的DML变化信息：
可以发现每天都有大量分区的INSERTS操作：
本库采用oracle自带统计信息任务，基本每天都会给表的统计信息进行更新。
默认不会马上失效cache游标，但是有个隐含参数控制失效窗口，默认是18000s(5个小时)：
容易导致在invalidation窗口超时发生硬解析，而awr分析发现问题期间系统IO较差，很多IO平均等待20ms+:
发现RMAN产生大量IO：
进一步调研发现本库的备份策略如下：
1、 每周六23:00全库备份，大约7TB，需要需要32小时；
2、 每天18:00发起聚集增量备份，最长大约需要19小时。
全库备份和聚集增量存在重合，而本库redo log存储是SSD、数据文件是SAS盘，因此导致IO读写性能较差。
以上分析只能解释硬解析发生的原因，但是为啥一个简单SQL解析需要2分钟呢？
……
到这里，大家不妨停一下，思考一下，如果是你，接下来你打算分几步来分析，又需要哪些信息来帮助你找到问题的根本原因呢…
思考时间
……
什么时候往下翻，由你决定…
……
硬解析时间长的原因
4.1 是系统负载太高导致资源争用?
分析了OSW数据，问题点没有异常！
4.2 是系统负载太高导致资源争用?
的确前面看到RMAN导致IO性能有所下降，但是如此简单的SQL需要解析2分钟无法解释！
4.3 是不是表太大了无法cache导致的
这个表的确很大，但是解析只需要元数据信息，这个表在反复读写操作，应该基本都在cache中了。
真相即将揭晓！！！
请关注上图中的视频号，并预约直播， 2月10日（周四）晚上八点，让我们一起开始一段福尔摩斯探案之旅！记得帮转发并预约直播哦。
