记一次Exadata DSKM hung故障的处理经过

原文地址: http://www.dbaleet.org/a_troubleshooting_experience_for_exadata_dskm_hung/

话说某年某月某日,当我还在人民银行处理一例紧急的故障,另外一个客户通过电话找到了我,这个客户只有Exadata和我有一些交集,虽然我们私交还不错,但是客户一般不轻易打我个人电话。看来情况有点严重,不出所料,电话那头客户果真有些焦急:

“刚才我们Exadata出问题了,现在每个节点都在产生大量dump文件,没多久就快要把本地磁盘空间给占满了。“

“日志中有看到报错吗?”

“报错倒是没有看到,只看到第四个DB节点的alert日志中有一句DSKM进程好像挂起了,具体什么原因也不清楚,然后DB节点就开始生成大量的dump,现在数据库的状态也好像也不大正常,已经影响到正常业务了。”
“是不是DSKM进程异常导致diag在做systemstate dump呀?”

“嗯, 应该是的”

“ASM和cell节点的alert中有看到错误吗?”

“没有看到!”

“你能不能临时处理一下,把这个dump文件备出来,然后把这个文件删掉?然后看空间有没有释放出来,如果情况比较紧急,就把第四个DB节点的CRS重启下?”  我意识到自己有些说漏嘴了,赶紧补充道:“这样吧,我现在在客户现场,我跟另外一位同事说一声,让他帮忙处理下”, 因为人行这边在开故障处理汇报小会,我也无暇顾及只能跟同事说完以后就继续忙我自己的事情了。

次日,因为同事刚好今天有事,我就让客户把之前的一些日志发到我邮箱,继续查找问题的原因。因为Exadata的内存较大,所以产生的systemstate dump也非常大,单个dump文件足有好几G,压缩以后也无法用邮件发送,只能让客户先保存到网盘,然后我再从网盘下载。

拿到日志以后,我首先检查了一下DB的alert日志,其它节点基本没有发现什么异常,但是第四个DB节点果然印着DSKM process hung的字样。

Wed Mar 13 11:55:12 2013
DSKM process appears to be hung. Initiating system state dump.
Wed Mar 13 11:55:12 2013
System State dumped to trace file
/u01/app/oracle/diag/rdbms/exadb/exadb4/trace/exadb4_diag_19389.trc

费力老鼻子的劲,终于把exadb4_diag_19389.trc这个dump文件从网盘取下来了(东北话)。这个时候发现自己犯难了,因为这个文件实在太大了,用vim打开了半个小时依然无果,还好我用的是Linux,用split命令根据进程号对这个文件进行简单的分割以后,这个庞然大物就被我肢解为成百上千个小文件。然后运用egrep匹配DSKM字样找到DSKM进程的进程号,根据这个进程号找文件DSKM进程的systemstate dump信息(因为大部分systemstate dump的信息量巨大,很多与这个case没有什么干系,所以以下只列出一小部分)。

有了systemstate dump问题就好办了,首先就是找到当时的shortstack:

Short stack dump:
ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1782<-sspuser()+112<-__restore_rt()<-semtimedop()+10<-
skgpwwait()+156<-ksliwat()+1821<-kslwaitctx()+162<-kslwait()+141<-ksarcv()+207<-ksbabs()
+323<-kszmain()+1985<-ksbrdp()+923<-opirip()+623<-opidrv()+603<-sou2o()+103<-opimai_real()
+266<-ssthrdmain()+214<-main()+201<-__libc_start_main()+244<-_start()+36

看名字感觉跟hung是这几个函数semtimedop()<-skgpwwait()<-ksliwat()<-kslwaitctx()<-kslwait()可能是比较重要的线索。

然后继续从systemstate dump中看到,当前的等待事件为rdbms ipc message.

Current Wait Stack:
0: waiting for 'rdbms ipc message'
timeout=0x77, =0x0, =0x0
wait_id=2429685 seq_num=4891 snap_id=1
wait times: snap=0.013241 sec, exc=0.013241 sec, total=0.013241 sec
wait times: max=1.190000 sec, heur=0.013241 sec
wait counts: calls=1 os=1
in_wait=1 iflags=0x5a8

rdbms ipc message多数时候是空闲等待大多数时候是空闲等待,当然也不一定。

因为挂起的是DSKM,这个进程在以前10g的版本中是没有的,所以觉还是稍微有些陌生,但是必然和disk monitor脱不了干系,所以下一步应该是找disk monitor的日志信息:

2013-03-13 11:53:46.299: [ DISKMON][6788:1246013760] dskm_process_msg7: processed msg
2535006 type KGZM_BCAST_OSS_IOCTL (0x000a), retcode 0
2013-03-13 11:53:52.251: [ DISKMON][6788:1193564480] dskm_hb_thrd_main6: timedout
2013-03-13 11:54:09.887: [ DISKMON][6788:1204054336] dskm_hb_thrd_main6: timedout

可以看到在DB的alert报dskm hung之前,disk monitor进程就已经报超时了。

从以上信息,借助MOS似乎就能推断出一些结论了:

Bug 16083346: DSKM PROCESS HUNG AND THEN RESTARTING THE INSTANCE

Bug 12752212 An unnecesary large systemstate generated when DSKM process hangs

难道就这样就交差了? NO! 但是毫无疑问,这个只是表象,问题的根源显然不在这里,理由很简单,得从DSKM的职责以及作用着手,究竟是什么动作导致了DSKM进程hang呢?

从官方文档: http://docs.oracle.com/cd/E14072_01/server.112/e10820/bgprocesses.htm 的知道,DSKM是disk monitor的一个slave进程,主要职责就是负责Exadata I/O 隔离(fencing)以及Cell中磁盘失败的监控和处理。

This process is active only if Exadata Storage is used. DSKM performs operations related to Exadata I/O fencing and Exadata cell failure handling.

那么Exadata DSKM异常hung肯定不是一个孤立的事件,肯定有其它诱因。顺藤魔瓜,果然找到了眼前一亮的信息:在cell07节点的/var/log/message中:

Mar 6 04:18:47 exacel07 kernel: sd 0:2:7:0: SCSI error: return code = 0x00070002
Mar 6 04:18:47 exacel07 kernel: end_request: I/O error, dev sdh, sector 852041728

同时在cell07的alert日志中也找到了以下内容:

Wed Mar 06 04:18:47 2013
IO Error on dev=/dev/sdh cdisk=CD_07_exacel07 [op=RD offset=852041728 (in sectors)
sz=1048576 bytes] (errno: Input/output error [5])
NOTE: Initiating ASM Instance operation: Query ASM Mode Status on 1 disks
FRA_CD_06_londvod01cel01 [0000012a-1a0a-cdbe-0000-000000000000]

以上两点充分证明了在DSKM hung以前cell07的FRA_CD_06盘存在扇区的损坏。

再在查看ASM DISKGROUP发现当前的空间已经超出了警戒值,USABLE_FILE_MB的大小为负数了, USABLE_FILE_MB在Exadata中代表的含义以前的文章已经详细描述过了:

http://www.dbaleet.org/exadata_faq_who_stoled_my_space/ 如果USABLE_FILE_MB为负数,也就意味着无法完成正常的ASM rebalance。翻开前文提到了RBAL进程,发现其状态同样是不正常的,其堆栈和等待事件与DSKM进程类似。

将所有线索串联起来,这个故事就通顺多了:

  • 首先在cell 07上发生了/dev/sdh磁盘的扇区发生损坏,导致了ASM磁盘状态不正常;
  • ASM尝试进行rebalance,但是由于当前的磁盘空间使用超出了安全值,使得ASM无法正常完成rebalance;
  • 由于ASM无法完成balance,导致与Exadata rebalance相关的进程进程RBAL和DSKM的状态不正常, 从而触发了DSKM进程的挂起;( Bug 16083346: DSKM PROCESS HUNG AND THEN RESTARTING THE INSTANCE);
  • 由于DSKM进程异常,自动触发系统diag进程收集systemstate dump的信息(这一部分属于hang manager新特性)。由于在早期的版本使用的是level 267进行dump,如果数据库的内存很大,会导致diag产生的dump文件非常大。(Bug 12752212 An unnecesary large systemstate generated when DSKM process hangs)

Comment

*

沪ICP备14014813号

沪公网安备 31010802001379号