客户某套Oracle rac业务库出现严重的library cache等待排查过程

简介

数据库版本：Oracle rac 19.9 EE

出问题时间段： 2024.04.07 16:48 到 17:00

核心数据库出现大量的enq: TX - row lock contention、library cache lock、library cache: mutex X、cursor: mutex S、cursor: mutex X等待。

分析方法

由于系统在17点已恢复正常，所以我们可以通过AWR、ASH、ADDM及一些系统视图来进行分析发生问题的时间段的数据库性能。

对应的AWR 快照范围为：29323 to 29324 ，对应16点到17点。

排查分析过程

排查1 ASH视图排查

查询等待事件统计：

1select substr(sample_time, 12, 5), event, count(<em>)   cnt<br> 2  from  dba_hist_active_sess_history<br> 3   where  sample_time between<br> 4          to_date('2024-04-07  16:47', 'yyyy-mm-dd hh24:mi') and<br> 5          to_date('2024-04-07  17:00', 'yyyy-mm-dd hh24:mi')<br> 6 -- and A.SQL_ID = 'cn9fqrd5w0841'    <br> 7 and event is not null<br> 8 group by event, substr(sample_time, 12, 5)<br> 9 having count(</em>) > 10<br>10 order by 1;<br>

会话阻塞情况：

排查2 ADDM报告分析

Top SQL Statements占用百分比最高，其中占用最高的SQL_ID "cn9fqrd5w0841" ，占用最高的等待事件为library cache lock和 "library cache: mutex X"，其SQL语句如下（已做脱敏）：

1update ABT_CDD_ILTO set ULQ_SEQ_ID=:1 , EVT_SEQ_ID=:2 ,<br> 2ABC_SEQ_TYP=:3 , LOT_ID=:4 , LOT_SPLT_ID=:5 , BOX_ID=:6 , SLOT_LO=:7<br> 3, MDL_ID=:8 , QW_ABC_SEQ_ID=:9 , GROUP_ID=:10 , ABC_STAT=:11 ,<br> 4ABC_QTY=:12 , ABC_STD_QTY=:13 , ABC_GRADE=:14 , QW_ABC_GRADE=:15 ,<br> 5ABC_TOICKLESS=:16 , QW_ABC_TOICKLESS=:17 , PRTY=:18 , QW_PRTY=:19 ,<br> 6COST_CODE=:20 , ABC_TOTAL_SWO_CLT=:21 , ABC_PT_CLT=:22 ,<br> 7ABC_SWO_CLT=:23 , ABC_PT_TYP=:24 , CUS_SL=:25 , TEMP_ABC_SEQ_ID=:26 ,<br> 8TAB_SL=:27 , TOOL_ID=:28 , TOOL_PORT_ID=:29 , QW_BOX_ID=:30 ,<br> 9QW_SLOT_LO=:31 , QW_PATO_ID=:32 , QW_PATO_VER=:33 , QW_OPE_LO=:34 ,<br>10QW_OPE_ID=:35 , QW_OPE_VER=:36 , QW_PROC_ID=:37 ,<br>11QW_TOOL_RUL_MODE=:38 , QW_TOOLG_ID=:39 , QW_TOOL_ID=:40 ,<br>12QW_ABC_STAT=:41 , QW_EVT_USR=:42 , QW_EVT_TIMESTAMP=:43 ,<br>13WE_PATO_ID=:44 , WE_PATO_VER=:45 , WE_OPE_LO=:46 , WE_OPE_ID=:47 ,<br>14WE_OPE_VER=:48 , WE_PROC_ID=:49 , WE_TOOL_RUL_MODE=:50 ,<br>15WE_TOOLG_ID=:51 , WE_TOOL_ID=:52 , CR_PATO_ID=:53 , CR_PATO_VER=:54 ,<br>16CR_OPE_LO=:55 , CR_OPE_ID=:56 , CR_OPE_VER=:57 , CR_PROC_ID=:58 ,<br>17CR_TOOL_RUL_MODE=:59 , CR_TOOLG_ID=:60 , CR_TOOL_ID=:61 ,<br>18LX_PATO_ID=:62 , LX_PATO_VER=:63 , LX_OPE_LO=:64 , LX_OPE_ID=:65 ,<br>19LX_OPE_VER=:66 , LX_PROC_ID=:67 , LX_TOOL_RUL_MODE=:68 ,<br>20LX_TOOLG_ID=:69 , LX_TOOL_ID=:70 , TST_JUDGE_TOOL_ID=:71 ,<br>21TST_JUDGE_TIMESTAMP=:72 , SLD_JUDGE_TOOL_ID=:73 ,<br>22SLD_JUDGE_TIMESTAMP=:74 , COIP_GRADE=:75 , ACT_STB_TIMESTAMP=:76 ,<br>23ACT_CMP_TIMESTAMP=:77 , TST_LOGOL_TIMESTAMP=:78 ,<br>24TST_LOGOT_TIMESTAMP=:79 , EVT_DEPT=:80 , EVT_CATE=:81 , EVT_USR=:82 ,<br>25EVT_TIMESTAMP=:83 , RELATE_USR=:84 , P1_TIMESTAMP=:85 ,<br>26P2_TIMESTAMP=:86 , SO_ID=:87 , WO_ID=:88 , QW_WO_ID=:89 ,<br>27DS_RECIPE_ID=:90 , AC_RECIPE_ID=:91 , MTRL_PROD_ID=:92 ,<br>28MTRL_GRADE=:93 , MTRL_LOT_ID=:94 , MTRL_BOX_ID=:95 ,<br>29MTRL_PALLET_ID=:96 , DEST_SOOP=:97 , STORAGE_LOC=:98 ,<br>30QRS_OVR_TLG=:99 , RMA_LO=:100 , PALLET_ID=:101 , BATCO_LO=:102 ,<br>31RWE_LO=:103 , DL_LO=:104 , BLK_TLG=:105 , OQC_LOTID=:106 ,<br>32OQC_SKIP_TLG=:107 , WO_IL_TIMESTAMP=:108 , SOIPPILG_TIMESTAMP=:109 ,<br>33SOIP_BOX_ID=:110 , RSL_DEPT=:111 , RSL_CATE=:112 , RSL_CODE=:113 ,<br>34TAB_ID=:114 , PROC_TLG=:115 , SOT_OPE_MSG=:116 , DET_CODE=:117 ,<br>35DET_CODE_LC=:118 , DET_CODE_CLT=:119 , LAYOT_ID=:120 ,<br>36X_AXIS_CLT=:121 , Y_AXIS_CLT=:122 , LOGOL_USR=:123 ,<br>37LOGOL_TIMESTAMP=:124 , QW_LOGOL_USR=:125 , QW_LOGOL_TIMESTAMP=:126 ,<br>38LOGOT_USR=:127 , LOGOT_TIMESTAMP=:128 , QW_LOGOT_USR=:129 ,<br>39QW_LOGOT_TIMESTAMP=:130 , MTRL_SLOT_LO=:131 , ABC_ADMIL_TLG=:132 ,<br>40REPAIR_TLG=:133 , ILSPECTIOL_TLG=:134 , ABLORMAL_TLG=:135 ,<br>41ITO_CID=:136 , ABC_IL_OUT_TLG=:137 , TPC_ID=:138 , CUSTOMER_ID=:139 ,<br>42TRAY_SLOT=:140 , EXT_1=:141 , EXT_2=:142 , EXT_3=:143 , EXT_4=:144 ,<br>43EXT_5=:145 , EXT_6=:146 , EXT_7=:147 , EXT_8=:148 , ABC_JUDGE=:149 ,<br>44EXT_10=:150 , EXT_11=:151 , EXT_12=:152 , EXT_13=:153 , EXT_14=:154 ,<br>45LILE_ID=:155 , EXT_16=:156 , RW_TLG=:157 , EXT_18=:158 , EXT_19=:159<br>46, EXT_20=:160 , PACK_LO=:161 , RW17_TLG=:162 , RW16_TLG=:163 ,<br>47TRAY_ID=:164 , PULL_TLG=:165 , MIL_GRADE=:166 , PROC_GRADE=:167 ,<br>48TELE_GRADE=:168 , TACADE_GRADE=:169 , QW_PROC_GRADE=:170 ,<br>49QW_TELE_GRADE=:171 , QW_TACADE_GRADE=:172 , DET_LAME=:173 ,<br>50DET_DATE=:174 , LD_CODE=:175 , OD_OPE_ID=:176 , OQC_LOT_JUDGE=:177 ,<br>51RISK_GRADE=:178 , OM_TLAG=:179 , ATT_TLAG=:180 , LM_TLAG=:181 ,<br>52CJ_TLAG=:182 , TY_TLAG=:183 , DATE_CODE=:184 , OQC_BALK_TLAG=:185 ,<br>53DATE_CODE_TIMESTAMP=:186 , UPCK_TIMESTAMP=:187 , WOSU_TIMESTAMP=:188<br>54, PGTP_TLAG=:189 , RY_OK=:190 , ZDLX_TLAG=:191 , BPZD_TLAG=:192 ,<br>55C_TLAG=:193  wOere ABC_SEQ_ID=:194<br>

1SYS@ORCLCDB> SELECT distinct KGLHDNSP,KGLHDNSD FROM X$KGLOB D WHERE KGLHDNSD like '%SQL AREA%'   ORDER BY KGLHDNSP; <br> 2<br> 3  KGLHDNSP KGLHDNSD<br> 4---------- ------------------------------------------------------------<br> 5         0 SQL AREA<br> 6        75 SQL AREA STATS<br> 7        82 SQL AREA BUILD<br> 8<br> 9SYS@ORCLCDB>  select to_char(5373954,'xxxxxxxxx') p3_hex, to_number('0052','xxxx')from dual; <br>10<br>11P3_HEX     TO_NUMBER('0052','XXXX')<br>12---------- ------------------------<br>13    520002                       82<br>

Reloads值也很高，可以考虑增大shared pool的大小。

如果在 SQL AREA 上的重新加载次数很高，那么需要检查游标是否被有效共享（重新加载的次数是指被缓存在 shared pool 中，但是使用时已经不在 shared pool 中）。如果游标已经有效共享，那么需要确认 shared pool 和 sga_target 是否足够大，如果 shared pool 有压力而没有足够的空间，那么有些缓存的游标会被从 shared pool 中清除。如果游标共享不充分，shared pool 会被这些不能被重用的游标占满，从而把那些可以重用的游标挤出 shared pool，进而引起在这些 SQL 重新执行时需要重新加载。游标共享充分，但由于 shared pool 空间过小也会引起可重用的游标被清除从而引发硬解析。不过最常见的情况还是游标无法共享。

继续查看游标的Version Count值：

如果version count大于200，则执行次数Executions列默认不收集（Why "Executions" and "Elap per Exec(s)" are 'Blank' in AWR for Some SQL Statements (Doc ID 1522547.1)）

由于SQL的子游标过多引起SQL解析时遍历library cache object handle链表需要很长时间，造成了library cache: mutex x等待。

子游标不共享导致出现很多的Version Count，但是子游标不共享的原因有很多，在MOS 438755.1中，Oracle提供了一个专门的脚本程序version_rpt.sql，用于协助诊断High Version Count问题。 运行完脚本后，可以使用如下的SQL分析：

1SELECT * FROM TABLE(VERSION_RPT('cn9fqrd5w0841'));<br>

该隐含参数从12.2数据库版本开始增加到8192。这会导致父游标不会被废弃，因此父级下的子游标会扩展到1024以上（这是12.1中的默认值），从而导致cursor mutex的并发问题。

从12.2开始，_cursor_obsolete_threshold的默认值大幅增加（从1024开始为8192）以便支持4096个PDB（而12.1只有252个PDB）。 此参数值是在多租户环境中废弃父游标的最大限制，并且不能超过8192。

但这个设置并不适用于非CDB环境，因此对于那些数据库，此参数应手动设置为12.1的默认值，即1024. 默认值1024适用于非CDB环境，并且如果出现问题，可以调整相同的参数，应视具体情况而定。

_cursor_obsolete_threshold首先在11.2.0.3中引入，默认值为100，然后在11.2.0.4中增加到1024

11.2.0.3: _cursor_obsolete_threshold=100

11.2.0.4: _cursor_obsolete_threshold=1024

12.1: _cursor_obsolete_threshold=1024

12.2: _cursor_obsolete_threshold=8192

在统计信息收集的时候，默认情况下 dbms_stats 的 no_invalidate 参数为 auto_invalidate ，意思 是 收集 完统计信息之后， 不 立即失效 统计 对象 相关 的cursor ，而是 采用滚动 失效 的方式 。这种做法 是为了 避免 统计信息收集之后产生大量的硬解析 。数据库会随机 的取一个小于_optimizer_invalidation_period 值来判断子游标的 INVALIDATE 时间，默认情况下是 18000 秒，即 5 个小时。

通过相关SQL语句分析了统计信息的情况，发现统计信息基本没有影响到该故障，若统计信息问题，那这种故障应该会频繁出现。

最后和运维人员讨论了一下，在故障点的时候执行了alter索引nomonitoring的操作，而且这个DDL的时间点和故障的时间点特别吻合，所以有理由怀疑这个DDL就是本次故障的导火索：

有关对表的索引做nomonitoring操作会导致游标失效的情况，我们已做过实验验证了：请参考：。

ASH和AWR结论：

● AWR中发现SQL_ID "cn9fqrd5w0841" 的Version Count很高，高达4300个子游标；对于版本过多的SQL，一次软解析甚至不如重新执行一次硬解析来的高效。过多的Version Count引起SQL解析时遍历library cache object handle链表需要很长时间，造成了library cache: mutex x等待。

● 游标 "cn9fqrd5w0841"不共享的原因主要是BIND_MISMATCH、ROLL_INVALID_MISMATCH和BIND_LENGTH_UPGRADEABLE，主要和绑定变量的范围和统计信息变动有关。

● 造成library cache lock严重等待事件的原因是大量的过期游标导致sql解析前花了大量时间去遍历library cache object handle

● 由于系统没有配置DDL跟踪，所以，DDL没办法深度排查。

排查4 硬解析次数较多

系统每秒硬解析达到23.6，大于经验值20，若大于20，说明SQL没有共享。

以下SQL的解析次数较高，需要对每条SQL语句进行排查

其它分析

还有其它的排查，例如告警日志、HANG ANALYSIS的日志，在MOS中搜索对应的bug，分析DBA_HIST_MUTEX_SLEEP等操作，分析后并没有很大收获，这里不再详细列出。

故障排查结论

对核心热点表ABT_CDD_ILTO的所有索引做了nomonitoring操作，导致该表的所有SQL游标全部失效，进行硬解析，导致SQL重载，引发大量的library cache lock等待，但因为绑定变量的原因很多子游标不能共享，生成了约4000多子游标，导致其version count过高，而过高的version count会导致 library cache: mutex X 等待。最后形成library cache lock和library cache: mutex X 相互阻塞的局面，导致系统hang住。

解决方案

最终客户的解决方案是配置10503的event！

1、 绑定执行计划

对于SQL_ID "cn9fqrd5w0841" 由于update语句的where条件使用的主键进行更新，所以，其实执行计划可以只保留1条足矣，因此，可以考虑使用SPM或SQL Profile来绑定执行计划。对其它Version count高的SQL也可以考虑使用SPM或SQL Profile来绑定执行计划是一个不错的选择。该操作不需要重启数据库。

后来，经过SQL Profile实战后，发现并不能减少version count，因为该update的执行路径是一样的，但因为绑定变量的缘故仍然会生成多个子游标。可见，纸上得来终觉浅。

2、 配置10503 event，可有效减少version count的数量

根据High Version Count Due To BIND_MISMATCH (Doc ID 336268.1)文档，可以通过event 10503调大会话级别的字符串bind buffer，以确保会话生成的游标buffer长度一致，建议将bind buffer调为2000(接近sql绑定变量的max_length)，可以如下配置

1ALTER system SET EVENTS '10503 trace name context forever, level 2000';<br>

1alter system set "_cursor_obsolete_threshold"=1024 scope=spfile sid='*';<br>