Systemstate Dump分析经典案例（上）

字数 4471阅读 1861评论 0赞 8

前言

本期我们邀请中亦科技的另外一位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’，结果见下图：
![1.jpg](/home/attachment/201707/24/994339_150087697291812.jpg)

出乎老K的意料，这些等待” cursor:pin S wait on X”的会话并不都在同一个idn上，而是分布在几个不同的idn上。
看起来问题比老K开始想象的要复杂，但是没有关系，以老K处理各种问题的经验来看，复杂问题只不过是多个简单问题的集合而已，需要的只是多一点耐心。

接下来，老K做的就是找到这些cursor对象mutex的持有者，以82d61778为例，选取其中一个正在等待这个对象的会话（sid:598）来分析，见下图
![2.jpg](/home/attachment/201707/24/994339_150087698292024.jpg)

这里需要解释一下
idn 82d61778：表明cursor对象
oper GET_SHRD：表明该会话正在以shared模式请求该mutex
(858, 0)：表明该mutex的持有者sid为858

找到了持有者，我们接着来看看sid为858的会话（858会话）在做什么：
![3.jpg](/home/attachment/201707/24/994339_150087699117438.jpg)

上图可以看出858会话也在等待”cursor:pin S wait on X”，而且从等待历史看，858会话的等待也持续了非常长的时间了；同样的方法，我们再来看看858会话请求的mutex又被谁持有了：
![4.jpg](/home/attachment/201707/24/994339_150087699955601.jpg)

我们看到了会话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建议读者不妨拿出笔画个图，我们就暂且称之为等待链图吧：
![5.jpg](/home/attachment/201707/24/994339_150087700772852.jpg)

4.3.3
继续分析SSD

这里我们暂且先不查“首要嫌疑人”，而是继续梳理等待事件关系，同上分析方法，我们找到trace中各IDN对象的持有者信息，如下：
![6.jpg](/home/attachment/201707/24/994339_150087701438425.jpg)

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

![8.jpg](/home/attachment/201707/24/994339_150087703241062.jpg)
![9.jpg](/home/attachment/201707/24/994339_150087703223264.jpg)

老K这里就不把上述所有会话的信息都列出来了，经过确认，各会话的均是在等待”cursor:pin S wait on X”等待事件，这时，我们再来更新一下我们的等待链图：
![10.jpg](/home/attachment/201707/24/994339_150087704637381.jpg)

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

离真相只差一步了，我们只需要分析library cache lock的源头就能解释整个谜团了，前面老K已经提到了分析library cache lock等待事件的方法了，
下一步只要结合trace文件定位library cache lock的阻塞关系，就能很快定位原因了。
由于篇幅有限，本期分享到这里先告一段落，下期分享继续，看老K如何一步一步由浅入深，分析问题，看看高大上的SSD分析是什么样的。敬请关注下期（未完待续...）

数据库

著作权归作者所有

如果觉得我的文章对您有用，请点赞。您的支持将鼓励我继续创作！

添加新评论0 条评论

Ctrl+Enter 发表

匿名评论

Systemstate Dump分析经典案例（上）

添加新评论0 条评论

作者其他文章

相关文章

相关问题

相关资料