技术人生系列·我和数据中心的故事（第七、八期）Systemstate Dump分析经典案例...

前言

本期我们邀请中亦科技的另外一位 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分析是什么样的。

4.3.4

SSD中library cache lock的分析

接上一期：
分析到这步，前边看似毫无头绪的问题似乎理清了，大量cursor pin S wait on X已经理清楚，所有的矛头走指向了sid 859

离真相只差一步了，我们只需要分析library cache lock的源头就能解释整个谜团了，前面老K已经提到了分析library cache lock等待事件的方法了，现在我们就来结合trace文件看看如何定位library cache lock的阻塞关系。
那好，我们就来看sid 859：

这个会话信息中我们能看到：
>> 会话在等待library cache lock等待事件，等待时间4429秒
>> 会话以S模式请求句柄为 700000209bb9d80 的library cache对象（request=S）
>> 句柄为700000209bb9d80的library cache对象是SYS.C_OBJ#_INTCOL#，是一个cluster（簇聚）对象。

我们就看到，会话859正在以S模式请求 700000209bb9d80 上的library cache lock而产生了等待，那么我们就可以确认系统中一定有另一个会话以X模式持有了700000209bb9d80上的library cache lock；同样，我们在trace文件中搜索关键字”700000209bb9d80”再过滤后能看到下面的条目：

我们定位到该条信息后，再确认该条信息所属的会话，确认其会话信息如下：

看到这里，大家有没有柳暗花明的感觉呢，我们看到持有 700000209bb9d80上library cache lock的会话是624，而会话624正在等待”cursor pin S wait on X”事件，等待的对象正是bbcee4f7； 现在我们再来完善上面的等待链图：

到最后， 我们发现在会话859和会话624之间，形成了死锁 ，具体的情况就是：
>> 会话859持有bbcee4f7上的mutex，请求700000209bb9d80上的library cache lock
>> 会话624持有700000209bb9d80上的library cache lock，请求bbcee4f7上的mutex
>> 其他会话产生大量的cursor pin S wait on X等待事件，都是由于859长时间持有bbcee4f7上的mutex未释放导致的

到了这一步，是不是一切谜团都解开了？我们的分析是不是就完成了呢？
↓
↓
↓
↓
↓
↓
答案是：NO

Part 5

根因分析

5.1 第三次头脑风暴
经常做根因分析的老K此时还有疑惑：
>> 如果当时不重启，而kill掉死锁链上的会话，问题是否会解决？
>> 会话859和会话624都在做什么，为什么会死锁？
>> 单个会话持有一个cursor的mutex，怎么会让系统处于夯住的状态？

5.2 柳暗花明之会话859
现在老K重点关注的就是如何解开上面的两个疑惑了，继续分析trace。
先看会话859，截取trace文件中的信息，如下：

从标黄处的信息我们知道，这是一个数据库的后台进程；我们可以通过查看trace中这个会话所属的进程信息如下：

先回答第二个问题：会话859在做什么？
后台进程是CJQ0，这个进程是ORACLE用来调度job的；我们知道，如果某个会话以S模式请求某个对象上的library cache lock，这个会话通常是在解析某个语句或者编译某个package时需要从library cache中查找该语句涉及对象的信息；在PROCESS 24的trace文件中查找“oper EXCL”关键字， 我们查到以下三条记录 ：

在PROCESS 24的trace文件中查找“ oper EXCL ”关键字，我们查到以下 三条记录 ： 
Mutex 7000001e7d04898(859, 0) idn bbcee4f7 oper EXCL
Mutex 7000001e5fbe4e0(859, 0) idn fb52493f oper EXCL
Mutex 7000001e8faa990(859, 0) idn a8bbc174 oper EXCL

可能有人会问？一个会话怎么同时有三个cursor？
大家不要忘了ORACLE数据库中有递归调用的说法，也就是说前端发起一条简单的sql，ORACLE后台实际上产生了一系列的递归调用，那些调用实际上也是一些sql的集合。通过idn值继续查找，提炼一下，当前正在解析的三条sql语句分别是：

这里说明一下：其实，SSD中对sql的递归调用关系是不体现的，不过从上面的三条sql语句老K还是能推断出其调用关系的；
CJQ0进程是用来调度 oracle  job的，从三条语句能大致的看到：a8bbc174是用来查询系统中job相关信息的sql， fb52493f是通过对象号用来查询某个对象的信息的sql，而bbcee4f7则是用来查询直方图信息的sql。
a8bbc174调用fb52493f，fb52493f调用bbcee4f7，如果这是bbcee4f7出问题，另外两个肯定无法正常执行。这里正是因为bbcee4f7无法完成解析，而导致其上层的fb52493f和a8bbc174阻塞；
新的疑点：三条SQL和C_OBJ#_INTCOL#有什么内在联系？
会话正在请求C_OBJ#_INTCOL#上的library cache lock而产生等待，而从这三条sql的文本来看，似乎都跟C_OBJ#_INTCOL#这个对象扯不上关系，这又怎么解释呢？有细心的读者可能已经注意到了，前面老K特意指出了C_OBJ#_INTCOL#是一个cluster（簇聚）对象，cluster对象不是表，而是用来存储多个表的共同列的，那这里我们就可以注意最底层调用的sql中的histgrm$对象是否与C_OBJ#_INTCOL#有关，我们来看看histgm$的定义：

又解开了一个谜题，histgrm$确实使用了C_OBJ#_INTCOL#这个cluster对象，所以在解析使用了histgrm$表的sql语句时，需要获取C_OBJ#_INTCOL#上的library cache lock。
5.3 柳暗花明之会话624
接下来，再来看看会话624，像分析会话859一样，把单个进程的trace摘出来，我们来截取部分信息如下：

从这里看，这是一个被调起的job进程，PROCESS号为42；

这不是一个数据库的后台进程，所以，相比于之前看到的859进程，我们能看到更多的信息，我们大致知道，这个进程是数据库调起的收集统计信息的job任务，在等待”cursor pin S wait on X”事件，等待的解析对象是bbcee4f7；
因为它以X模式持有C_OBJ#_INTCOL#这个对象的library cache lock而阻塞了关键的会话859，那么我们来看看它为什么会持有这个library cache lock；我们到PROCESS 42的进程信息中搜索oper EXCL的关键字，搜索到两条相关信息如下：

同样，我们也能从sql语句的语义上猜到两者的递归调用关系；

会话624持有了C_OBJ#_INTCOL#和I_OBJ#_INTCOL#的library cache lock，其中I_OBJ#_INTCOL#是CLUSTER的索引。现在所有疑团都解开了。可以放松一下，从头捋顺思路了。

Part 6

情景再现

终于看到了全景，看看数据库故障时刻在做什么。

在本场景中，数据库自动收集统计信息任务调度J000进程收集整个数据库统计信息，在收集cluster对象时，数据库只能使用analyze的方式分析；
J000先收集C_OBJ#_INTCOL#统计信息，接着继续使用analyze的方式收集其索引I_OBJ#_INTCOL#的统计信息；
因为C_OBJ#_INTCOL#对象的统计信息被更新，因为histgrm$与C_OBJ#_INTCOL#的关联关系，与histgrm$相关的sql（包括bbcee4f7）也就需要重新解析；
这时CJQ0进程定时查询系统JOB时，需要硬解析，递归调用bbcee4f7时对其进行解析；
解析的过程中需要以S模式请求持有histgrm$及其相关对象（也就包括C_OBJ#_INTCOL#及其索引I_OBJ#_INTCOL#）的library cache lock；

在J000使用analyze的过程中，同样需要执行相关递归sql，需要进行硬解析，也就调用了上面说到的关键sql bbcee4f7；
而此时J000进程正在analyze索引I_OBJ#_INTCOL#，也就以X模式持有了I_OBJ#_INTCOL#上的library cache lock；
在J000使用analyze的过程中，同样需要执行相关递归sql，需要进行硬解析，也就调用了上面说到的关键sql bbcee4f7；
所以最后造成了死锁。

Part 7

问题定位

其实在上述分析的过程中，我们基本可以判断为bug， （MOS）:1628214.1 Database Appears to Hang with Deadlock Involving SYS.C_COBJ# or C_OBJ#_INTCOL# While Statistics Maintenance Job is Running

Part 8

写在最后

到上面为止，我们已经定位bug，也获得了事中和事后的解决方案，不过老K更关注的是大家是否能从这个CASE中获得一些收获，这里不妨问问自己：
>> Systemstatedump中的cursor p in S wait on X 我会查了吗？
>> Systemstatedump中的library cache lock 我会查了吗？
>> 如果我要模拟让我的数据库夯我会做吗？
>> 还有一个没有回答的问题？如果下次再遇到同样的问题，我能通过杀掉死锁链条里的进程解决这个问题么？

欢迎加入我们的qq群一同讨论：227189100。

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/30787320/viewspace-2078113/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/30787320/viewspace-2078113/