运维的故事,故障处理系列(五)

真实案例:折磨老姜的三天三夜
老姜因为家庭的缘故,对部分工作进行了“放权”。他也把几个核心的事情安排到具体的人。现在一般就是开开会,监督下工作上的进度。只要不出什么大的状况,老姜都按时下班去接他的孩子。身为老一辈的DBA,老姜已经顺利的从技术岗位转到了管理岗位。不过管理也有管理的痛,老姜需要保障人员不流失,还要招人,还要对各种类型的人员进行考核,还得管理日常的事务,每天邮件都能收上百封。此时此刻,老姜正在查阅邮件,突然二线小朱急匆匆的走过来,老姜一看不对劲,低沉的问道:“怎么了?”
小朱头上冒着汗,轻松说道:“核心系统CRM现在运行的很慢,都是log file sync的等待事件,我们怀疑是存储上的问题,但是没有证据。现在局方负责人很着急,希望我们能够给出解决办法。”

老姜不假思索的说道:“走,我和你去看一下情况。”
一到现场小朱就打开了刚刚生成的AWR报告指着给老姜看,然后说道:“领导,你看,现在的等待事件的耗时都集中在I/O类型的上面,如db file sequential read这个在一个小时的报告里面等待了17973秒,而log file sync也等待了17447秒。他们的平均等待一个是65ms,一个是79ms。刚刚我检查了一下系统负载的情况,CPU的负载是正常的,系统的提交次数,我通过user calls / user commits + user rollbacks是大于25次的,证明没有提交上的问题。 ”

 
老姜问道:“有没有检查过日志切换的频率?”
小朱答道:“这个我们之前看过,是正常的。我们检查了LGWR的Trace,我们发现了下面的一些信息”

*** 2014-01-11 14:34:49.333
Warning: log write time 22850ms, size 2KB
*** 2014-01-11 14:34:51.692
Warning: log write time 1650ms, size 104KB
*** 2014-01-11 14:36:23.280
Warning: log write time 16680ms, size 3KB
*** 2014-01-11 14:36:31.259
Warning: log write time 660ms, size 8KB
*** 2014-01-11 14:38:02.595
Warning: log write time 16090ms, size 9KB
*** 2014-01-11 14:38:11.100
Warning: log write time 740ms, size 6KB
*** 2014-01-11 14:39:45.532
Warning: log write time 19130ms, size 2KB
*** 2014-01-11 14:39:51.275
Warning: log write time 780ms, size 9KB

“这些都是短时间里面迅速出现的,可以证明写的时候很慢。”小朱接着说道。
老姜说道:“还是先检查log file parallel write的情况,从现在的这些表面现象上看都是I/O的问题,如何确保是不是真的I/O存在问题,我们看一下log file parallel write的情况就知道了。

 
不过接下来的情况让老姜和小朱又一次吃了一惊,因为log file parallel write的等待时间几乎可以忽略到不计,这种情况说明I/O不存在任何问题。
为了验证这个问题,老姜立马把小李叫过来说道:“小李,你帮我测试一下用dd把裸设备的数据备份到文件系统上,测试一下速度,记得,最好要测试3-4次,把平均值告诉我。”
老姜吩咐完小李后,对小朱说道:“你在去看一下数据库,有任何异常的情况赶紧处理,现在还只是慢而已,客户还能够使用,只是感知度比较差,我就怕待会这种慢会引发hang的情况,导致不能使用,那就糟糕了。”
老姜接着对小王说道:“小王,你把这个情况还有Trace给专家组的同事反馈一下,把邮件发出来,我们请他们帮我们一起协助分析这个问题。还有,你马上开一个1级的SR,把这些信息也上传上去,你要一直跟进这个事情,负责和后台人员的交流。他们找你要什么信息,你就取出来给他们。”
老姜把事情安排好,自己也开始登陆到终端开始查起来了,虽然老姜有一段时间没碰技术了,但是好歹是9i的OCM,底子还是在这里的,老姜一步一步的进行着分析。对了log file sync,老姜以前也做过一些深入的研究,在他脑海里面最深入的是大师tanel poder的图。这幅图把log file sync分成了6个步骤。当用户发起提交的时候,用户进程一定会去通知LGWR进程工作,LGWR接收到工作命令后,就发起写日志的动作,把log buffer里面的内容都写到文件上,这是一个顺序写的过程,写完之后,LGWR就会告诉前台进程我已经干完活了。而前台进程接收到了LGWR干完活的信息,就会在屏幕上给我们显示“Commit complete”。整个过程如下图所示,而整个物理写的过程会调用操作系统的函数syscall来完成,而这个过程就是刚刚我们看到的log file parallel write,这也就是侧面的说明物理写是很快的。那既然这样,就证明是其他方面出了问题,比如进程之间的交互,可能出现了问题。但是这个是说不过去的,因为整个系统上还有一个很耗时间的等待事件db file sequential read,这个也是很慢的,写入没出问题,难道是读出现了问题?

 
此时应用的负责人老许过来问老姜:“怎么数据库这么慢,有没有查到是什么引起的?这么慢,前台业务人员都没法用啊。”
老姜心想,这个时候还没有定论,只是怀疑存储是一个可能性的阶段,暂时还是不要说太多,于是老姜说道:“我们还在查这个问题,暂时还没有发现是什么引起的。”
老许听完一脸不开心:“你们赶紧查啊。这个问题现在闹到局方老大哪里去了。从种种现象来看,你们数据库很大嫌疑啊,是不是有什么bug,需要打补丁啊。”
类似这种嘲讽的语气,老姜听多了,老姜深谙其中的一个道理就是,除了局方负责人,我不用给任何人交待这个问题。同时老姜也很郁闷,这也是困扰每一个,每次一出问题,应用的人还有主机的人都认为是数据库的问题,搞的干数据库的人鸭梨山大。去年有个小伙还说不错的,但是顶不住这种鸭梨,愤然离职而去。导致人员被动变动。对运维工作来讲十分不利,好不容易人家把环境摸清楚了,各方的运维人员也混熟悉了,被鸭梨给吓跑了,所以老姜平时也会定期给大家减减压,适当的搞一搞轻松的休闲活动。
老姜默默的说道:“老许,我们已经开了CASE,上传了一些资料给我们的专家组和Oracle Support,他们会尽快帮助我们分析原因。我们这边也在尽力的去查,至于是什么问题,现在还不好下定论。”
此时老姜后面突然出现了好几个人,其中一个就是局方整个系统的负责人老刘,老刘说:“老姜,去808会议室,我们几个开个简短的会议,你们几个把情况都反映下,我们现在前台有很多投诉的,这个问题现在要抓紧分析处理。”
每一次出现重大故障的时候,局方负责人都喜欢开简短的会议,开这种会议的好处就是能够把事情的严重性说一遍,然后听听各方的意见,最后根据意见来下达进一步指示。
会议一开始,老刘就说道:“这个系统是CRM系统,也是我们最核心的系统,所以一定要抓紧时间处理,现在我们收到了很多前台的投诉,你们主机侧、应用侧、数据库、存储侧都分别说说看,现在问题出在哪儿?”
老姜第一个抢着站起来说道:“刘总,是这样的,我们现在数据库的压力集中在db file sequential read和log file sync这两个等待事件上面,现在消耗的等待时间很多,从初步的情况上我们来判断有几个可能性。
1.存储上出现短暂的hang,导致时快时慢,这个我们现在正在找人用dd命令进行一个测试,马上就可以把测试结果拿出来。
2.第二个可能性是程序交互性存在延迟,就是进程和进程之间的通信缓慢,这个我们需要在观察一下是否主机上资源存在着瓶颈,是否因为进程申请不到资源而导致通信缓慢。
这俩点是我们暂时对这个问题的研究方向。“
接下来刘总分别问了主机侧和应用侧还有存储侧,这些人分别表示自己这一侧目前没看到任何的异常情况。
老姜一听心想,这和以前一样,都怀疑我数据库,没事,有那一次我不能证明我自己没问题么?来者不拒,我们一定会打个漂亮的翻身仗。
大家说完后刘总接着说道:”老姜,你就按照你这个思路继续,二个小时之后,我们在这里在碰头,把问题的进度在汇报一遍。“
散会后老姜急急忙忙的问小李:”情况怎么样?DD读写性能如何?“
小李斩钉截铁的说道:”我做了5次测试,存储的读写速度在130-150m/s的范围内,看上去不像是存储的问题。“
”嗯,刚才开会存储的工程师也阐述了他们的观点,他们也认为不是存储的问题。那会不会是存储的链路有问题?要是链路有问题也会出现时快时慢的现象。不过按照你的测试,没有出现过慢的情况对吧?“老姜又问道。
小李答道:”我做了几次测试,都是很平稳的,没有太大的波动,没有发现时快时慢的现象。”
“好的,那你在检查一下整个主机的资源的情况,把出现问题之前和出现问题之后的资源情况做一下对比,主机上都部署了OSWatcher,你去搞几张图出来。”老姜说道。
老姜接下来又问小王:“专家组那边有什么反馈?Oracle support上怎么说?”
小王答道:“Oracle Support认为是存储I/O问题,我们和他们还在进一步的反馈,当然也不排除是Bug的可能性,他们怀疑是某个Bug导致出现了log file sync缓慢的问题,现在还在进一步分析,而专家组的同事说可能是由于进程交互出现了问题,也在继续的查。”
“好的,这一块你要继续跟进,和他们保持沟通。”老姜又说道。
接下来老姜又问了小朱系统的情况,小朱简单的介绍了一下现在的一些状况,看来除了慢,没有什么特别的征兆。老姜觉得这个问题好像比较复杂,于是就拨通了公司专家组的热线:“喂,我要求现在到现场安排一个专家过来,帮忙分析问题。”
不到一个小时,公司就把专家小林派到了现场。小林到现场之前在路上已经充分的了解了情况,小林提出了一个建议。“目前日志放在裸设备上面,我们先考虑迁移到文件系统上边。”
在小林来之前,老姜也已经把整个OSWatcher的数据看了一遍,现在和以前的资源负载没发生什么大的改变。所以老姜提出来的两个假设基本上是可以排除掉了。到目前为止大家都已经没有了思路,在没思路的情况下是很可怕的,当小林提出了这种思路之后,大家也都欣然的接受。小林立马在专用于备份的目录上创建了几组新的日志,并切换了过去,意想不到的情况居然发生了log file sync的等待次数大大的下降。这更加让人感觉到迷惑。难道是因为业务高峰期过了的原因吗?
老姜对小林说道:“等会跑一份现在的AWR报告出来,看一下等待事件和消耗时间的情况,现在业务高峰期已经过了,可能会有些影响。马上我要去开会。”
“对了,Oracle Support上怎么说?”老姜问道。
小王说道:“后台人员认为是Bug导致的,他们正在分析是那一个Bug引起的。这是他们认为可能存在的情况。“

Bug 8490879 Long "log file sync" latencies due to broadcast on commit scheme - fixed in 10.2.0.4.4, 10.2.0.5 
Bug 8220734 Long "log file sync" wait in RAC - fixed in 10.2.0.4.4, 10.2.0.5 
Bug 7716356 Long "log file sync" latencies with broadcast on commit scheme in RAC - fixed in 10.2.0.5 
Bug 7610362 Long "log file sync" waits in RAC with broadcast on commit in RAC - fixed in 10.2.0.4.4, 10.2.0.5 
Bug 7452373 "log file sync" timeout is not configurable - fixed in 10.2.0.5

俩个小时的新一轮开会,老姜把刚刚自己说的两点可能性进行了验证,并否定了这些可能性,老姜说道:“目前可能存在着两个新的方向:
1.可能是由于Oracle Bug导致的缓慢。目前我们把Trace上传上去了,后台正在分析可能是命中了哪一种bug。
2.另外一种可能性是主机的集群软件和数据库的进程交互出现了问题,刚刚我们把数据库日志从裸设备迁移到文件系统上,log file sync的数量就减少了,而LGWR的Trace也不在有新的告警了。这一块因为我们不是很懂主机的集群软件,我需要主机的工程师帮忙检查下集群软件是否异常。“
刘总听完说道:“主机务必全力的配合数据库来查这个问题。如果定位出了Bug,立马安装补丁。你们在催一催Oracle的人,最后现场派个工程师过来。”
散会后,老姜开始安排人员的调度,像这种CRM的系统,属于最核心最核心的系统,影响范围可谓相当的深远,一出故障就非常伤脑筋。必须安排人7*24小时的攻克难关,每天晚上都需要至少安排三个人在这边,一个一线(和SR沟通),一个专家(负责继续查问题)。还有对外接口人(负责统管大小事务及和外界沟通)。所以老姜自觉的留下做对外接口人。
大家伙一起研究下午老姜说的两种可能性,老姜觉得现在的思路也都堵死了,一个依赖于Oracle后台SR,一个依赖于主机层,那么我们还能在做些什么呢?
不知不觉到了晚上,老姜安排人员分批去吃饭,晚上的时间因为业务量少,根本就没有影响,所以很多情况没有再现,但是老姜、小林,小王三个人今天得通宵找问题原因。三个人又仔细的把今天一天的情况检查了一遍,还是没有发现什么明显的问题。
老姜有把出问题期间,整个DBA_HIST_ACTIVE_SESS_HISTORY相关的信息查了一遍,会不会是应用改动导致的问题呢?在业务量多的情况下就产生,业务量少的情况下就不发生,这种情况也是有可能的。但是查来查去也都没查出什么有价值的信息。
就这样过去了一天一夜,大家还是没有定位出问题。第二天一大早,SR突然更新了,一个好消息,后台和我们一样检查了cpu和内存都没出现问题。而是因为bug 7716356 导致的missing post引起的log file sync。

LGWR writes are very fast and yet 80% of times FG processes timed out while waiting for LGWR post. I have checked OS stats as well and there is no CPU or memory starvation on the machine. So it appears that the long LFS waits and timeouts are caused by a missing post. This looks like bug 7716356 that is RAC specific.

于是老姜把这个问题和刘总进行了反馈,希望在中午的时间能够一台一台的安装补丁。而刘总却说不行,这个操作只能放到晚上执行。老姜听完心想晚上就晚上吧,于是就去安排工作。小林和小王白天可以休息,晚上过来继续跟进这个事情。白天让二线小朱和一线小李继续跟进这个问题。大家互相把工作交接好。此时此刻老姜困的不行,年纪这么大了,熬了一个通宵早就累的够呛,但是没办法,谁叫自己是个管理者,出了问题自己得身先士卒,所以老姜硬着头皮继续的坚持着。直到中午老姜才休息了一会。
今天一天的情况也很怪异,log file sync的情况好了很多,这让老姜开始有点怀疑是不是因为那个bug引起的问题。下午老姜自己登上了一台服务器,把日志重新切换回裸设备,对lgwr做了两次truss,truss这个工具能够帮助我们追踪操作系统的调用,老姜在追踪过程中发现了一个些问题。

truss -faied -D -o /tmp/trace.out -p 3842
Base	time	stamp:	1389629043		Tue	Jan	14	0:04:03	CST	2014
29396/1:	siginfo:	SIG#0
29396:	psargs:	ora_lgwr_crmdb1	
29396/1:	175.1173     12.0148   kaio(AIOWRITE,	781,	0x381816600,	18432,	0x12782E0075D35F78)=0
29396/1:	75.9295	11.3157	kaio(AIOWRITE,	781,	0x38375F000,	3072,	0x0EBA6C0075310CC8)	=0
29396/1:	56.5273	0.8171	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=0
29396/1:	34.3783	0.8128	semtimedop(85,	0xFFFFFFFF7FFFDCE4,	1,	0xFFFFFFFF7FFFDCD0)	=0

老姜发现LGWR执行写操作会去调用操作系统的kaio模块的函数AIOWRITE去执行一个的写操作。这是一个异步I/O的操作。老姜开始怀疑,是否是操作系统的kaio这个内核模块出现了异常。老姜还发现大部分执行AIOWRITE的时间都在0.8秒左右,而慢的有2次,分别是12秒和11秒。而一旦慢,LGWR就会在Trace文件上写一下。老姜把这个问题迅速反馈给主机侧的人员,而主机侧的人员接到这个问题,也准备开SR。
晚上大家伙按照Oracle说的,开始打了补丁,把补丁打完后,开始做各方面的检查和测试,测试期间发现patch虽然安装上了,使用裸设备,log file sync的问题依然还是存在。于是老姜赶紧让小王把patch回滚掉了。
老姜心想,果然不是Oracle Bug导致的,这个思路也行不通。还是从主机层面上着手这个问题。必须研究清楚是不是kaio的问题。于是老姜问小林:“有没有检查过操作系统的日志?“老林说道:”我已经检查过了,两台主机的操作系统均无报错。”
老姜找到了主机的人员,问道:“你们原厂的工程师今天来了吗?”
主机的小蔡说道:“来了,我们刚刚检查了硬件日志,我们发现内存出现了问题。FMA 提示该内存需要更换,我们已经在前天就把这个出错的内存禁用掉了,应该不会有什么问题。“
老姜一听,觉得有蹊跷,于是说道:“这个比较巧啊,你们内存出问题的时候和我们数据库出故障的时间雷同。这个问题你们赶紧升级吧。我也发现了一些问题,就是数据库在使用异步I/O的时候时快时慢。这个你们在贴道你们主机开的SR上去吧。”
就这样一夜又过去了,老姜也被折腾的够累,晚上轮流休息了几个小时。不过老姜心里觉得主机现在的嫌疑其实是非常大的,目前数据库层面已经无法在继续查下去,只能督促主机侧进行问题的升级。
第三天一大早,刘总就开会问大家昨天晚上的情况如何?老姜和小蔡把查出来的一些情况做了汇报,目前已经升级到了Oracle Solaris原厂美国的团队。后台正在全力分析。
刘总很严厉的说道:“今天已经是第三天了,这个问题必须解决,既然内存坏了,时间点又吻合,我们就把坏的内存换掉,晚上把主机、数据库都重启一遍。”
“嗯,我们也是这么考虑的!”老姜和小蔡同时答道。这个时候数据库和主机也统一了战线。
散会后,老姜就安排人员的休息。他让昨晚通宵的小林和小王先休息。自己依旧在岗位上坚持着,两天两夜了,老姜就休息了5-6个小时。不过他已经看到了一丝曙光。
不久,主机小蔡突然过来拍了下老姜的肩膀说道:“主机这边的SR有回复了,因为内存损坏,而这部分内存原本是Oracle数据库SGA使用了一些,我们禁用掉了这些内存,而操作系统 kernel 在不断尝试去撤销使用数据库共享内存(SGA)某些内存页面, 但是并未成功,这就导致只要是操作关于这部分内存数据的都会慢,而不操作这部分内存数据的都会很快。这个是主机上的一个bug,bug号是15679676。具体情况我已经给你发邮件了,你看一下。”
老姜打开邮箱。看了一下这个bug的描述。
“在 ISM/DISM 段页面内存出现可纠正或不可纠正的内存错误时,页面回收线程尝试解锁任何已经要准备要回收的页面.但是这些页面被 SGA 锁定,无法被回收。遇到这种 SGA 产生的锁, Solaris 会执行慢的 I/O 程序, 导致数据库性能下降。”
老姜感慨道:“原来如戏啊,是这个回收程序无法回收,导致Solaris执行慢的I/O程序。怪不得。不过这个问题也算是很奇葩了,所有的表象都是I/O,而实际出问题的确是内存。那这个问题怎么解决?晚上把内存换了?然后重启主机和数据库,你们要不要安装这个Patch的?“
小蔡也跟着叹气:”哎,我们以为禁用就没事了,没想到数据库的SGA能把内存一直锁住,不让线程回收。我们今天晚上实施换内存,Patch这个先不安装,因为这个是属于内核相关的Patch。“
老姜又问道:”我们观察了操作系统日志?为什么没有查到任何相关的报错?“
小蔡说道:”我们是通过硬件日志看到的。而且你们应该看的是虚拟的两个分区上的主机的日志。这台物理机上做了几个分区的。这就好比我们的windows机器上安装了vmware,你们看vmware上的主机日志,当然都是正常的咯。“
”哦,原来是这样,这次还要是谢谢你们咯!“老姜说道。
终于晚上把内存换掉后,重启了主机和数据库,系统恢复了正常。这三天三夜把老姜折磨的够呛,作为一个管理人员,老姜把对出现故障的各个节点把控,人员调度的安排还是很值得大家学习的。

分享到: 更多

Post a Comment

Your email is never published nor shared. Required fields are marked *