原文地址： 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）
Leave a Reply