Systemstate Dump分析经典案例（上）

Posted 2020-09-29

前言

本期我们邀请中亦科技的另外一位Oracle专家老K来给大家分享systemstate dump分析的经典案例。后续我们还会有更多技术专家带来更多诚意分享。

老K作为一个长期在数据中心奋战的数据库工程师，看到小y前期的分享，有种跃跃欲试的感觉，也想把我日常遇到的一些有意思的案例拿出来分享讨论，希望我们都能从中获得些许收获，少走弯路。同时本文涉及到很多基础知识，又涉及看似枯燥的trace分析，但老K还是建议大家耐心看完本文。

精彩预告

• 如何分析cursor:pin S wait on X？

• 如何分析library cache lock？

• 如何分析解读systemstate dump？

• 如何快速应急处理以及收集信息？

温馨提示

温馨提示：该篇为老K诚意之作，篇幅略长，如微信阅读有所不适，可以移步QQ群：227189100下载文本阅读，并同时关注我们的微信号“中亦安图”与我们交流。

Systemstate Dump我们暂且叫SSD吧

Part 1

问题来了

一个周末的早上，客户来电，两节点RAC数据库其中一个节点夯死。

现象描述：

>> 节点hang死，SYS和普通用户均无法登陆

>> 受影响范围只在其中一个节点，其他节点能正常对外提供服务

>> hang死节点有大量异常等待事件cursor:pin S wait on X以及少量library cache lock。

Part 2

故障处理及信息收集

老K第一反应是让客户快速收集数据库hanganalyze 和SSD，马上通过杀进程的方式重启问题节点数据库，优先恢复数据库服务。

最终，客户在收集完信息发给老K后，重启了问题节点数据库，一切又恢复了正常。

Part 3

知识点扫盲

cursor:pin S wait on X

什么时候会产生这个等待事件？

当一个会话以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 事件。

如何定位其等待的对象？

该等待事件的P1参数idn，实际上就是sql语句的hash_value，也就是说通过该等待事件的P1参数即可定位等待的实际对象。

如何查找该事件的源头？

在定位了该等待事件所等待的对象后，该对象MUTEX的持有者即为该等待事件的源头。

在trace文件中，可以通过oper EXCL关键字查找到持有者。

library cache lock

什么时候会产生这个等待事件？

当一个会话对library cache中的对象（主要是TABLE /INDEX/CLUSTER/PROCEDURE等）进行修改（通常是指DDL操作）时，会以X模式持有该对象的library cache lock；当一个会话在解析sql需要用到某个对象时，会以S模式请求该对象的library cache lock；

举一个简单的例子，一个会话（SESSION_A）正在对表TAB_A进行DDL操作，另一会话（SESSION_B）开始执行与TAB_A相关的sql语句，那么此时SESSION_B此时会等待library cache lock事件。

如何定位其等待的对象？

该等待事件的P1为handle address即为等待对象在library cache 中的句柄地址，可唯一标示该内存对象。

如何产生该事件的源头？

在定位了该等待事件所等待的对象后，持有该对象的X模式library cache lock的会话即为等待事件的源头。

在trace文件中，可以通过对象的地址关键字和mode=X关键字查找到该等待事件的源头。

那么数据库异常时间内到底发生了什么，我们通过trace入手，还原现场。

Part 4

故障分析

环境介绍：

操作系统 AIX 5.3

数据库 ORACLE 10.2.0.5 两节点RAC

4.1 第一次头脑风暴

现有“情报”

>> RAC系统一个节点夯

>> 数据库中存在大量cursor:pin S wait on X 等待事件和少量library cache lock等待事件

>> 有收集的hanganalyze 信息和SSD  trace文件

这两个等待事件的原理是什么？

出现上述等待事件后系统的表现是什么？

当一个系统出现大量cursor:pin S wait on X 等待事件时，通常原因是由于一个会话的sql硬解析异常，阻塞了这条SQL的软解析，这种情况下，可能的源头就只有一个，只要把源头找到，问题就迎刃而解了。

4.2 入手分析

4.2.1

SSD入手分析

常规处理方法：对于cursor:pin S wait on X等待事件，只需关注其等待对象，是同一个对象还是多个不同对象，如果都是等待在一个对象上，情况相对简单，要找到这个等待的对象，那就需要到SSD的trace中查找关键字

’waiting for ‘cursor:pin S wait on X’，

结果见下图：

出乎老K的意料，这些等待” cursor:pin S wait on X”的会话并不都在同一个idn上，而是分布在几个不同的idn上。

看起来问题比老K开始想象的要复杂，但是没有关系，以老K处理各种问题的经验来看，复杂问题只不过是多个简单问题的集合而已，需要的只是多一点耐心。

接下来，老K做的就是找到这些cursor对象mutex的持有者，以82d61778为例，选取其中一个正在等待这个对象的会话（sid:598）来分析，见下图

这里需要解释一下

idn 82d61778：表明cursor对象

oper GET_SHRD：表明该会话正在以shared模式请求该mutex

(858, 0)：表明该mutex的持有者sid为858

找到了持有者，我们接着来看看sid为858的会话（858会话）在做什么：

上图可以看出858会话也在等待”cursor:pin S wait on X”，而且从等待历史看，858会话的等待也持续了非常长的时间了；同样的方法，我们再来看看858会话请求的mutex又被谁持有了：

我们看到了会话859持有了bbcee4f7的mutex，然后它又在等待”library cache lock”事件。

问题查到这，我们停下来想一想。

4.3.2

第二次头脑风暴

>> 会话598在等待cursor:pin S wait on X，阻塞者sid为 858

>> 会话858在等待cursor:pin S wait on X事件，阻塞者sid为859

>> 会话859在等待library cache lock事件，阻塞者待查

>> library cache lock的阻塞者是谁，很有可能是一个“元凶之一”

>>是不是大量的cursor:pin S wait on X都被library cache lock阻塞，如果是的话问题就变得简单了

如果看到这里你还晕晕的，那么老K建议读者不妨拿出笔画个图，我们就暂且称之为等待链图吧：

4.3.3

继续分析SSD

这里我们暂且先不查“首要嫌疑人”，而是继续梳理等待事件关系，同上分析方法，我们找到trace中各IDN对象的持有者信息，如下：

我们看到，859/858/815等会话目前持有mutex，并且阻塞了其他会话以shared模式获取其持有的mutex；其中859会话为我们刚刚找的等待链的源头，858会话为我们刚刚找到的等待链的中间部分，作为一个mutex的持有者，同时又在等待另一个mutex，那我们再来看看其他会话都在等什么：

老K这里就不把上述所有会话的信息都列出来了，经过确认，各会话的均是在等待”cursor:pin S wait on X”等待事件，这时，我们再来更新一下我们的等待链图：

分析到了这里是不是已经柳暗花明了？前面理不清的大量cursor:pin S wait on X已经理清楚，所有的矛头走指向了sid 859

离真相只差一步了，我们只需要分析library cache lock的源头就能解释整个谜团了，前面老K已经提到了分析library cache lock等待事件的方法了，

下一步只要结合trace文件定位library cache lock的阻塞关系，就能很快定位原因了。

由于篇幅有限，本期分享到这里先告一段落，下期分享继续，看老K如何一步一步由浅入深，分析问题，看看高大上的SSD分析是什么样的。敬请关注下期（未完待续...）