ITPUB论坛-中国最专业的IT技术社区

 找回密码
 注册
查看: 29342|回复: 23

[精华] 技术人生系列 · 我和数据中心的故事(第七、八期)Systemstate Dump分析经典案例

[复制链接]
认证徽章
论坛徽章:
3
双子座
日期:2016-01-25 21:04:27目光如炬
日期:2016-02-28 22:00:00火眼金睛
日期:2016-02-29 22:00:01
发表于 2016-3-8 12:21 | 显示全部楼层 |阅读模式
本帖最后由 xiao__y 于 2016-3-8 12:21 编辑

前言


本期我们邀请中亦科技的另外一位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’,结果见下图:
1y.jpg

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

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

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

找到了持有者,我们接着来看看sid为858的会话(858会话)在做什么:
3y.jpg

上图可以看出858会话也在等待”cursor pin S wait on X”,而且从等待历史看,858会话的等待也持续了非常长的时间了;同样的方法,我们再来看看858会话请求的mutex又被谁持有了:
4y.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建议读者不妨拿出笔画个图,我们就暂且称之为等待链图吧:
绘图1.jpg

4.3.3
继续分析SSD

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

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

7y.jpg

8yJPG.jpg

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

分析到了这里是不是已经柳暗花明了?前面理不清的大量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:
9w.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”再过滤后能看到下面的条目:
10w.jpg

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

11w.jpg

看到这里,大家有没有柳暗花明的感觉呢,我们看到持有700000209bb9d80上library cache lock的会话是624,而会话624正在等待”cursor pin S wait on X”事件,等待的对象正是bbcee4f7;现在我们再来完善上面的等待链图:
绘图3w.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文件中的信息,如下:

12w.jpg

从标黄处的信息我们知道,这是一个数据库的后台进程;我们可以通过查看trace中这个会话所属的进程信息如下:
13w.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语句分别是:

14w.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$的定义:
15w.jpg

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

从这里看,这是一个被调起的job进程,PROCESS号为42;
18w.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的关键字,搜索到两条相关信息如下:


同样,我们也能从sql语句的语义上猜到两者的递归调用关系;
20w.jpg

19w.jpg

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

情景再现


终于看到了全景,看看数据库故障时刻在做什么。
总结4w.jpg

在本场景中,数据库自动收集统计信息任务调度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中的cursorin S wait on X 我会查了吗?
>> Systemstatedump中的library cache lock 我会查了吗?
>> 如果我要模拟让我的数据库夯我会做吗?
>> 还有一个没有回答的问题?如果下次再遇到同样的问题,我能通过杀掉死锁链条里的进程解决这个问题么?

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


第一期:技术人生系列 · 我和数据中心的故事(第一期)小机上运行Oracle需要注意的进程调度bug。
http://www.itpub.net/thread-2051086-1-1.html
第二期:技术人生系列 · 我和数据中心的故事(第二期)——风险提醒之Oracle RAC高可用失效
http://www.itpub.net/thread-2051474-1-1.html
第三期: 技术人生系列 · 我和数据中心的故事(第三期)-中亦科技关于数据库文件损坏风险的提醒
http://www.itpub.net/thread-2051721-1-1.html
第四期:技术人生系列 · 我和数据中心的故事(第四期)-导致Oracle性能抖动的参数提醒
http://www.itpub.net/thread-2051954-1-1.html
第五期:技术人生系列 · 我和数据中心的故事(第五期)—清算/报表/日终跑批程序之性能优化案例(一)
http://www.itpub.net/thread-2053028-1-1.html
第六期:技术人生系列 · 我和数据中心的故事(第六期)-Oracle内存过度消耗风险提醒

http://www.itpub.net/thread-2053618-1-1.html
认证徽章
论坛徽章:
3
双子座
日期:2016-01-25 21:04:27目光如炬
日期:2016-02-28 22:00:00火眼金睛
日期:2016-02-29 22:00:01
发表于 2016-3-8 12:22 | 显示全部楼层
这期是第七期和第八期两期合集

第一期:技术人生系列 · 我和数据中心的故事(第一期)小机上运行Oracle需要注意的进程调度bug。
http://www.itpub.net/thread-2051086-1-1.html
第二期:技术人生系列 · 我和数据中心的故事(第二期)——风险提醒之Oracle RAC高可用失效
http://www.itpub.net/thread-2051474-1-1.html
第三期: 技术人生系列 · 我和数据中心的故事(第三期)-中亦科技关于数据库文件损坏风险的提醒
http://www.itpub.net/thread-2051721-1-1.html
第四期:技术人生系列 · 我和数据中心的故事(第四期)-导致Oracle性能抖动的参数提醒
http://www.itpub.net/thread-2051954-1-1.html
第五期:技术人生系列 · 我和数据中心的故事(第五期)—清算/报表/日终跑批程序之性能优化案例(一)
http://www.itpub.net/thread-2053028-1-1.html
第六期:技术人生系列 · 我和数据中心的故事(第六期)-Oracle内存过度消耗风险提醒
http://www.itpub.net/thread-2053618-1-1.html

使用道具 举报

回复
论坛徽章:
2
白羊座
日期:2016-03-16 21:46:15金牛座
日期:2016-04-15 08:21:49
发表于 2016-3-8 12:55 | 显示全部楼层
感谢楼主无私奉献,分享精彩的案例,谢谢!

使用道具 举报

回复
求职 : 数据库管理员
招聘 : Java研发
认证徽章
论坛徽章:
6328
ITPUB9周年纪念徽章
日期:2014-05-02 10:36:402011新春纪念徽章
日期:2014-12-29 12:11:142010广州亚运会纪念徽章:卡巴迪
日期:2014-08-06 08:44:25马上加薪
日期:2017-01-10 16:49:34马上有钱
日期:2017-01-10 16:49:34马上有钱
日期:2014-12-26 15:39:08马上有钱
日期:2014-12-26 15:39:08马上有房
日期:2014-12-26 15:42:55马上有车
日期:2017-01-10 16:49:34马上有钱
日期:2014-12-31 17:16:56
发表于 2016-3-8 13:38 | 显示全部楼层
建议搞个微信群

使用道具 举报

回复
论坛徽章:
15
秀才
日期:2015-09-21 09:46:16双子座
日期:2016-01-15 10:47:09秀才
日期:2016-01-13 12:14:26秀才
日期:2015-12-25 15:31:10双子座
日期:2015-12-15 09:58:52巨蟹座
日期:2015-11-17 17:17:02白羊座
日期:2015-11-09 13:49:13双子座
日期:2015-11-02 10:25:11水瓶座
日期:2015-08-25 15:30:042015年新春福章
日期:2015-03-06 11:57:31
发表于 2016-3-8 14:14 | 显示全部楼层
这个难度大了,遇到了基本是直接提CASE

使用道具 举报

回复
论坛徽章:
1
蜘蛛蛋
日期:2012-11-20 13:47:55
发表于 2016-3-8 19:07 | 显示全部楼层
写的还真详细。太长了,不过看起来还比较经典,下回也自己分析分析systemstate dump试试

使用道具 举报

回复
论坛徽章:
70
夏利
日期:2013-09-29 21:02:15天蝎座
日期:2015-12-11 09:52:33马上有对象
日期:2014-02-19 11:55:14马上有钱
日期:2014-02-19 11:55:14马上有房
日期:2014-02-19 11:55:14马上有车
日期:2014-02-19 11:55:14马上有车
日期:2014-02-18 16:41:112014年新春福章
日期:2014-02-18 16:41:11兰博基尼
日期:2014-01-02 19:02:10保时捷
日期:2013-12-28 20:27:38
发表于 2016-3-8 23:18 | 显示全部楼层
好文,加精。

使用道具 举报

回复
认证徽章
论坛徽章:
3
双子座
日期:2016-01-25 21:04:27目光如炬
日期:2016-02-28 22:00:00火眼金睛
日期:2016-02-29 22:00:01
发表于 2016-3-9 09:59 | 显示全部楼层
vage 发表于 2016-03-08 23:18好文,加精。
谢谢!vage

使用道具 举报

回复
论坛徽章:
5
2011新春纪念徽章
日期:2011-02-18 11:42:48ITPUB十周年纪念徽章
日期:2011-11-01 16:26:292012新春纪念徽章
日期:2012-01-04 11:57:36ITPUB 11周年纪念徽章
日期:2012-10-09 18:16:002013年新春福章
日期:2013-02-25 14:51:24
发表于 2016-3-9 10:32 | 显示全部楼层
分析的好详细啊,学习了

使用道具 举报

回复
论坛徽章:
112
罗罗诺亚·索隆
日期:2017-02-08 15:50:20布鲁克
日期:2017-02-09 14:54:03秀才
日期:2017-02-22 15:14:12蒙奇·D·路飞
日期:2017-04-10 18:09:45布鲁克
日期:2017-04-18 14:36:29
发表于 2016-3-9 14:35 | 显示全部楼层
本帖最后由 zergduan 于 2016-3-9 14:40 编辑

非常感谢分享~

我有一个疑问,为什么不直接看hangananlyze的trc?

里面应该有明显cycle chain呀,应该直接就可以定位到两个相互block的session~
一个SSD动辄就是几十MB,我觉得首先应该以hanganalyze为入口,最快的定位cycle chain,找到block的源头,先解决hang的问题,保证应用运行
然后在通过其定位到ssd中内容找到原因,这样的过程比较效率吧?

使用道具 举报

回复

您需要登录后才可以回帖 登录 | 注册

本版积分规则

TOP技术积分榜 社区积分榜 徽章 电子杂志 团队 统计 虎吧 老博客 知识索引树 读书频道 积分竞拍 文本模式 帮助
  ITPUB首页 | ITPUB论坛 | 数据库技术 | 企业信息化 | 开发技术 | 微软技术 | 软件工程与项目管理 | IBM技术园地 | 行业纵向讨论 | IT招聘 | IT文档 | IT博客
  ChinaUnix | ChinaUnix博客 | ChinaUnix论坛 | SAP ERP系统
CopyRight 1999-2011 itpub.net All Right Reserved. 北京皓辰网域网络信息技术有限公司版权所有 联系我们 网站律师 隐私政策 知识产权声明
京ICP证:060528号 北京市公安局海淀分局网监中心备案编号:1101082001 广播电视节目制作经营许可证:编号(京)字第1149号
  
快速回复 返回顶部 返回列表