作者DBA小y·2017-07-24 14:25

系统工程师·中亦科技

Systemstate Dump分析经典案例（下）

字数 5240阅读 1487评论 0赞 6

前言

接上一期：（上一期的阅读方法：关注“中亦安图”公众号后回复‘007’）

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：
![1.jpg](/home/attachment/201707/24/994339_150087725756724.jpg)

这个会话信息中我们能看到：
>> 会话在等待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”再过滤后能看到下面的条目：
![2.jpg](/home/attachment/201707/24/994339_150087726749768.jpg)

我们定位到该条信息后，再确认该条信息所属的会话，确认其会话信息如下：
![3.jpg](/home/attachment/201707/24/994339_150087727937767.jpg)

看到这里，大家有没有柳暗花明的感觉呢，我们看到持有700000209bb9d80上library cache lock的会话是624，而会话624正在等待”cursor:pin S wait on X”事件，等待的对象正是bbcee4f7；现在我们再来完善上面的等待链图：
![4.jpg](/home/attachment/201707/24/994339_150087753256911.jpg)

到最后，我们发现在会话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文件中的信息，如下：
![5.jpg](/home/attachment/201707/24/994339_150087751612544.jpg)

从标黄处的信息我们知道，这是一个数据库的后台进程；我们可以通过查看trace中这个会话所属的进程信息如下：
![6.jpg](/home/attachment/201707/24/994339_150087750358829.jpg)

先回答第二个问题：会话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语句分别是：
![7.jpg](/home/attachment/201707/24/994339_150087748454861.jpg)

这里说明一下：其实，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$的定义：
![8.jpg](/home/attachment/201707/24/994339_150087746388854.jpg)

又解开了一个谜题，histgrm$确实使用了C_OBJ#_INTCOL#这个cluster对象，所以在解析使用了histgrm$表的sql语句时，需要获取C_OBJ#_INTCOL#上的library cache lock。

5.3 柳暗花明之会话624

接下来，再来看看会话624，像分析会话859一样，把单个进程的trace摘出来，我们来截取部分信息如下：
![9.jpg](/home/attachment/201707/24/994339_150087745035033.jpg)

从这里看，这是一个被调起的job进程，PROCESS号为42；
![10.jpg](/home/attachment/201707/24/994339_150087743991630.jpg)

这不是一个数据库的后台进程，所以，相比于之前看到的859进程，我们能看到更多的信息，我们大致知道，这个进程是数据库调起的收集统计信息的job任务，在等待”cursor:pin S wait on X”事件，等待的解析对象是bbcee4f7；
因为它以X模式持有C_OBJ#_INTCOL#这个对象的library cache lock而阻塞了关键的会话859，那么我们来看看它为什么会持有这个library cache lock；我们到PROCESS 42的进程信息中搜索oper EXCL的关键字，搜索到两条相关信息如下：
![11.jpg](/home/attachment/201707/24/994339_150087741976584.jpg)
同样，我们也能从sql语句的语义上猜到两者的递归调用关系；
![12.jpg](/home/attachment/201707/24/994339_150087741058419.jpg)
![13.jpg](/home/attachment/201707/24/994339_150087741154104.jpg)

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

Part 6
情景再现

终于看到了全景，看看数据库故障时刻在做什么。
![14.jpg](/home/attachment/201707/24/994339_150087739373813.jpg)

在本场景中，t1时刻，数据库自动收集统计信息任务调度J000进程收集整个数据库统计信息，在收集cluster对象时，数据库只能使用analyze的方式分析；

t2时刻，因为C_OBJ#_INTCOL#对象的统计信息被更新，因为histgrm$与C_OBJ#_INTCOL#的关联关系，与histgrm$相关的sql（包括bbcee4f7）也就需要重新解析；

t3时刻，J000先收集C_OBJ#_INTCOL#统计信息，接着继续使用analyze的方式收集其索引I_OBJ#_INTCOL#的统计信息；

t4时刻，这时CJQ0进程定时查询系统JOB时，需要硬解析，递归调用bbcee4f7时对其进行解析；
解析的过程中需要以S模式请求持有histgrm$及其相关对象（也就包括C_OBJ#_INTCOL#及其索引I_OBJ#_INTCOL#）的library cache lock；

t4时刻，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:pin S wait on X 我会查了吗？
>> Systemstatedump中的library cache lock 我会查了吗？
>> 如果我要模拟让我的数据库夯我会做吗？
>> 还有一个没有回答的问题？如果下次再遇到同样的问题，我能通过杀掉死锁链条里的进程解决这个问题么？

如果你的答案都是肯定的，那么老K觉得这篇分享很有价值。
如果以上问题你还有疑问，可以通过微信或者QQ共同交流讨论。

数据库 Oracle

著作权归作者所有

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

添加新评论0 条评论

Ctrl+Enter 发表

匿名评论

Systemstate Dump分析经典案例（下）

添加新评论0 条评论

作者其他文章

相关文章

相关问题

相关资料