由于alert日志中出现大量的row cache enqueue lock等待，并且数据库中存在大量的建表删表操作， 因此运维人员判断可能是因为ID2319957.1- Sessions Hang on "row cache lock" (dc_objects) While Creating & Dropping a Table Concurrently导致数据库hang死，但因为客户的数据库环境row cache lock告警在alert中一直是频繁存在的，因此客户并不信任分析结果，因此便有了这次故障分析的案例。
根据客户的描述，简单将故障当天情景重现：
故障当天早上8点10，客户应用侧反映系统健康运行时长及在线用户数指标中断。
8点30发现部分应用侧节点出现HTTP无法访问告警。
8点38发现系统登录页面可以正常访问，但登录失败。
8点47接到数据库运维人员通知，发现数据库出现大量活动会话，但数据库处于hang死状态，运维人员请求重启数据库。
9点20数据库重启完毕。
9点21重启各个业务节点，9点38业务节点重启完毕，业务恢复正常。
原因分析：
根据客户提供的alert日志、ssd trace文件以及数据库版本：10.2.0.5，我们分析原因如下：
21日6点40，数据库运行遇到BUG(Bug 11738097 CHECKPOINT NOT HAPPENING AND SMON PROCESS HUNG WITH WAIT EVENT 'ENQ: RO - FAST), SMON出现ENQ: RO自死锁（同一会话之间出现不正常的死锁），导致CHECKPOINT无法正常进行。8点06分，数据库实例1出现日志切换（LOG FILE SWITCH），由于CHECKPOINT未完成，因此LOG FILE SWITCH无法完成，在系统日志出现：
Thu Mar 21 08:06:24 CST 2019
Thread 1 cannot allocate new log, sequence 256000
Checkpoint not complete
Current log# 2 seq# 255999 mem# 0: /oradata/CWGKVPD/redo2_1
Current log# 2 seq# 255999 mem# 1: /oradata/CWGKVPD/redo2_2
此时系统中的写操作均无法完成，等待日志切换完成。所有新会话无法连接到数据库，修改操作均无法完成。已经连上的会话可以进行只读操作。
综上所述，数据库BUG导致了CKPT无法正常完成检查点，最终导致日志切换无法正常完成，导致最终宕机。
详细分析过程如下：
第一步：将alert日志中出现ssd trace通过ASS生成可读性好的日志文件。
第二步：根据alert日志的中的告警时间点和我们已生成的ASS日志文件，可整理出如下时间序列的可疑事件表：
| Alert告警信息 | 分析 |
| 1号节点03:16分出现kill session信息 | Oracle自己主动将会话杀死，问题不大 |
| 1号节点03:42分出现WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=231告警并产生相关的ssd trace | 通过生成的ASS日志文件，可发现3个可疑点： 5: waiting for 'rdbms ipc message' [Latch received-location:] 229:waiting for 'row cache lock' [Rcache object=0x36f0c99e0,] 231:last wait for 'ksdxexeotherwait' [Rcache object=0x36f0c99e0,] Cmd: Create Table 经分析： 5号后台进程在等待DRM同步的相关消息，经确认，为正常情况。 229和231进程均在等待资源号为0x36f0c99e0的dc_objects的row cache lock，经确认，并不会影响系统的正常使用。 |
| 2号节点3点52分出现WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=127 告警并产生相关的ssd trace | 通过生成的ASS日志文件，可发现6个可疑点: 15: waiting for 'rdbms ipc message' 16: waiting for 'enq: RO - fast object reuse'[Enqueue RO-00020010-00000001] 60: waiting for 'enq: RO - fast object reuse'[Enqueue RO-0002003C-00000001] 89: waiting for 'latch free' [Latch 60008ef8] 98: waiting for 'SGA: allocation forcing component growth' Cmd: Truncate Table 127:last wait for 'ksdxexeotherwait' [Rcache object=0x2ed478c20,] Cmd: Create Table 经分析： 127号进程以S模式申请资源号为0x2ed478c20的dc_objects的ROW CACHE ENQUEUE LOCK，但该LOCK被89号进程以X模式占有，同时89号进程又在等待资源号为60008ef8的latch，但该latch被98号进程持有，98号进程在等待sga resize完成。该等待链并不会造成数据库可能会影响数据库性能但此时并没有造成数据库hang死。 60号进程以S模式申请enq: RO - fast object reuse锁，但锁Enqueue RO-0002003C-00000001被15号进程以X模式占有，同时16号进程以X模式申请Enqueue RO-00020010-00000001锁，但Enqueue RO-00020010-00000001被15号进程以SS模式占有同时Enqueue RO-00020010-00000001被16号进程自己以SSX模式占有。注意，此时虽然16号进程以X模式申请自己以SSX模式占有的Enqueue RO-00020010-00000001，但并没有形成死锁。 这里关键的15号进程在等待rdbms ipc message消息。 此时数据库仍然是正常运行的。 注：15号进程为ckpt进程，16号进程为smon进程. |
| 1号节点4点05分出现WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=229 告警并产生相关的ssd trace | 通过生成的ASS日志文件，可发现3个可疑点： 5: waiting for 'rdbms ipc message' [Latch received-location:] 229:waiting for 'row cache lock' [Rcache object=0x36f0c99e0,] 231:last wait for 'ksdxexeotherwait' [Rcache object=0x36f0c99e0,] Cmd: Create Table 通过分析发现： 229、231和3点42分的ssd trace等待的对象仍然是一样的。此时仍然在等资源号为0x36f0c99e0的dc_objects的row cache enqueue lock. 5号后台进程在等待DRM同步的相关消息，经确认，为正常情况。 此时数据库仍然是正常的。 |
| 2号节点5点52分出现 Immediate Kill Session#: 1794, Serial#: 25766 | 实例2杀用户进程报错，但32444是一个用户进程，对系统故障无直接影响 |
| 2号节点6点38分出现 Thu Mar 21 06:38:58 CST 2019 | 实例2 遇到BUG12551583，经确认和宕机无直接关系 |
| 1号节点6点40分出现WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=206 告警并产生相关的ssd trace | 通过生成的ASS日志文件，可发现6个可疑点： 5: waiting for 'rdbms ipc message' [Latch received-location:] 15: waiting for 'rdbms ipc message' 16: waiting for 'enq: RO - fast object reuse'[Enqueue RO-00010010-00000001] 206:last wait for 'ksdxexeotherwait' [Rcache object=0x2be85cd98,] 311:waiting for 'enq: TC - contention' [Enqueue TC-00010137-00000000] 314:waiting for 'enq: TC - contention' [Enqueue TC-0001013A-00000000] 首先我们229和231号进程的row cache enqueue lock等待已经不见了，对比发现3点42分与6点40分这两个后台进程对应的会话号一致，操作系统进程号也一致。可见，在6点40时，这两个进程已经得到了row cache enqueue lock，并不是这两个会话引起的数据库hang死。 现在再来分析： 5号后台进程在等待DRM同步的相关消息，经确认，为正常情况。 206号进程在等待资源号为0x2be85cd98的dc_objects的row cache lock，经确认，并不会影响系统的正常使用。 311号进程以X模式申请Enqueue TC-00010137-00000000锁，而Enqueue TC-00010137-00000000锁被15号进程以SS模式占有同时也被311号进程自己以SSX模式占有。 314号进程以X模式申请Enqueue TC-00010137-00000000锁，而Enqueue TC-00010137-00000000锁被15号进程以SS模式占有同时也被314号进程自己以SSX模式占有。 此时15号进程一直在等待rdbms ipc message消息。 16号进程以X模式申请Enqueue RO-00010010-00000001锁，但Enqueue RO-00010010-00000001锁被16号进程以SSX模式占有，此时16号进程形成自死锁。但16号进程是SMON进程，由于SMON进程因为死锁的缘故一直持有Enqueue RO锁，直接导致CKPT进程无法扫描fast object reuse检查点队列，所以一直无法完成检查点。此时虽然无法做检查点，但由于数据库内仍存在inactive日志组，所以数据库部分操作仍然可以正常使用。 查询MOS上发现： SMON进程遇到了Bug 11738097 : CHECKPOINT NOT HAPPENING AND SMON PROCESS HUNG WITH WAIT EVENT 'ENQ: RO - FAST。导致系统的CHECKPOINT无法正常进行，此时系统已经处于不正常状态，系统可能存在部分操作无法正常进行的问题。 |
| 1号节点7点20分出现 FIX9322219: kjzhrepl.sessnum_kjzhrept (13) and data.data_kjzhadat.num_kjzhsdat (11) are out of sync kjzhresync: trying to resynchronize with DIAG | DIAG遇到BUG 12551583，确认和宕机无直接关系 |
| 1号节点7点21分出现 kjzhresync: timed out | DIAG遇到BUG 12551583，确认和宕机无直接关系 |
| 1号节点7点50分出现 FIX9322219: kjzhrepl.sessnum_kjzhrept (13) and data.data_kjzhadat.num_kjzhsdat (11) are out of sync kjzhresync: trying to resynchronize with DIAG | DIAG遇到BUG 12551583，确认和宕机无直接关系 |
| 1号节点7点51分出现 kjzhresync: timed out | DIAG遇到BUG 12551583，确认和宕机无直接关系 |
| 1号节点7点51分出现杀会话 Immediate Kill Session#: 1941, Serial#: 46788 Immediate Kill Session: sess: 0x3b3ae3710 OS pid: 23005 Thu Mar 21 07:51:38 CST 2019 Process OS id : 23005 alive after kill Errors in file | 系统自动杀会话失败，但是是一个用户会话，对系统故障无直接影响 |
| 1号节点7点56分出现WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=190 告警并产生相关的ssd trace | 通过生成的ASS日志文件，可发现6个可疑点： 5: waiting for 'rdbms ipc message' [Latch received-location:] 15: waiting for 'rdbms ipc message' 16: waiting for 'enq: RO - fast object reuse'[Enqueue RO-00010010-00000001] 190:last wait for 'ksdxexeotherwait' [Rcache object=0x2be85cd98,] 311:waiting for 'enq: TC - contention' [Enqueue TC-00010137-00000000] 314:waiting for 'enq: TC - contention' [Enqueue TC-0001013A-00000000] 经确认：206号进程的row cache enqueue lock锁等待已经消失，并且此时的会话号与之前出现等待时会话号一致，再次证明row cache enqueue lock并不是导致数据库hang死的原因。 经分析： 190号进程在等待资源号为0x2be85cd98的dc_objects的row cache lock，经确认，并不会影响系统的正常使用。 311、314仍然是在等15号进程持有的两个不同的TC锁。15号进程在等待rdbms ipc message 16号进程仍然是自死锁。并且已经等待超过120秒了。此时系统处于带病工作状态。 |
| 1号节8点的时候出现 Immediate Kill Session#: 1646, Serial#: 2712 Immediate Kill Session: sess: 0x3b2a80eb0 OS pid: 26283 | 系统自动杀会话，确认和宕机无直接关系 |
| 1号节点8点02分的时候出现 FIX9322219: kjzhrepl.sessnum_kjzhrept (11) and data.data_kjzhadat.num_kjzhsdat (9) are out of sync kjzhresync: trying to resynchronize with DIAG | DIAG遇到BUG 12551583，确认和宕机无直接关系 |
| 1号节点8点06分的时候出现 Thread 1 cannot allocate new log, sequence 256000 Checkpoint not complete Current log# 2 seq# 255999 mem# 0: /oradata/CWGKVPD/redo2_1 Current log# 2 seq# 255999 mem# 1: /oradata/CWGKVPD/redo2_2 | 此时数据库内已无inactive日志组，导致数据库已1号实例无法分配新的日志组，之前已经切换的日志组由于检查点无法完成，一直均处于active状态，此时1号节点已无法处理写操作。 |
| 1号节点8点27分出现 MMNL absent for 1201 secs; Foregrounds taking over | MMNL进程死掉 |
| 1号节点8点37分出现 WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=19告警并产生相关的ssd trace WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=234 | 16: waiting for 'enq: RO - fast object reuse'[Enqueue RO-00010010-00000001] SMON自死锁仍旧存在。 |
| 1号节点8点51分出现 PMON failed to delete process, see PMON trace file | PMON杀进程失败 |
| 1号节点9点出现 DBW1: terminating instance due to error 472 Thu Mar 21 09:00:33 CST 2019 Instance terminated by DBW1, pid = 11466 Thu Mar 21 09:00:39 CST 2019 Instance terminated by USER, pid = 24738 | 此时出现了两个数据库被关闭完成的提示。其中一个是DBW1后台进程发现系统故障后自动关闭数据库。基本上同时，DBA也发现了问题，手工关闭了数据库 |
至此，此次故障的原因已经很明了了，并不是因为alert告警中频繁出现的row cache enqueue lock而是因为遇到了smon自死锁Bug 11738097 : CHECKPOINT NOT HAPPENING AND SMON PROCESS HUNG WITH WAIT EVENT 'ENQ: RO – FAST。
而通过在MOS查询发现此BUG Oracle未提供补丁修复，因此该故障无法通过打补丁解决，一旦触发BUG，只能通过重启数据库实例来解决。
处置建议
最终我们给了客户两个建议：
- 暂时性整改建议：
客户的系统中存在频繁创建和删除表，因此触发该BUG的机会高于其他系统，另外ROW CACHE ENQUEUE WAIT TOO LONG也会引起数据库性能下降，甚至部分业务失败。因此为减少类似问题出现，建议客户数据库系统定期重启（比如每三个月主动重启一次）。
- 最优处置方式：
由于该BUG目前ORACLE不提供补丁包，因此无法打补丁解决该问题，将数据库升级到11.2.0.4以上可以解决该问题，因此尽快升级数据库是最佳的解决方案。
如果暂时无法升级数据库，此类问题只需要提前预知，就可以通过重启存在RO锁的实例来解决该问题（只重启一个节点，业务不会中断），而故障爆发时由于日志无法切换，会导致单节点重启时被挂起，需要同时重启两个实例，会导致业务中断。
通过加强对CKPT的监控来防范，提前预知故障，提前重启实例就可避免类似本次事件再次发生。通过在D-SMART中设置运维经验预警，当active日志组个数大于2的时候触发检查数据库中是否存在enq: RO - fast object reuse等待事件并且SMON进程是否处于hang状态即可提前发现该bug。
扫一扫
2349
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
