前言
本期我们邀请中亦科技的另外一位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分析是什么样的。敬请关注下期(未完待续...)