Hadoop运维记录系列(五)

dfee

今天集群神秘崩溃，影响范围较大，分析故障原因比较有趣，特此记录一下。之前也发生过类似的事情，不过没想起写blog，今天正好抓出log来写了。

当时的状况是，下午16点左右，集群处于比较繁忙的状态，突然集群数台服务器崩溃，已经无法ssh远程连接服务器，只好找ops重启服务器，然后就是正常的重启datanode和tasktracker。先恢复起来，再去看log，但是去看hadoop log的时候就心寒了。因为直接关电源重启，hadoop log没有任何错误记录。应该来说，只是记录到INFO，没有记录到故障就死锁，然后就重启了，所以log4j没有记录下任何信息，log4j在架构里处于比较高的层级太高端了。只能记应用存活以前的log。应用挂了，log4j也没有存活的理由了。所以，没办法，去看syslog。

数台机器的syslog也只记录到系统重启以前的正常状态，死锁后的状态完全没有。只在一台服务器的syslog奇妙的捕获到了异常。
01.505605 Apr  3 15:59:43 hadoop-node-31 kernel: INFO: task java:7437 blocked for more than 120 seconds.
02.505606 Apr  3 15:59:55 hadoop-node-31 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
03.505607 Apr  3 15:59:55 hadoop-node-31 kernel: java          D ffff810290cab860     0  7437      1          7484  7383 (NOTLB)
04.505608 Apr  3 15:59:55 hadoop-node-31 kernel:  ffff8104a0f51e18 0000000000000086 0000000000001d0d 0000000000007500
05.505609 Apr  3 15:59:55 hadoop-node-31 kernel:  00000000ffffffda 000000000000000a ffff8105638cb100 ffff810290cab860
06.505610 Apr  3 15:59:56 hadoop-node-31 kernel:  001806cf1be0ca78 000000000001246f ffff8105638cb2e8 0000000300000000
07.505611 Apr  3 16:10:01 hadoop-node-31 kernel: Call Trace:
08.505612 Apr  3 16:10:01 hadoop-node-31 kernel:  [<ffffffff8006467c>] __down_read+0x7a/0x92
09.505613 Apr  3 16:10:01 hadoop-node-31 kernel:  [<ffffffff8006716d>] do_page_fault+0x414/0x842
10.505614 Apr  3 16:10:01 hadoop-node-31 kernel:  [<ffffffff8005dde9>] error_exit+0x0/0x84
11.505615 Apr  3 16:10:01 hadoop-node-31 kernel:   
12.505616 Apr  3 16:10:01 hadoop-node-31 kernel: python invoked oom-killer: gfp_mask=0x280d2, order=0, oomkilladj=0
13.505617 Apr  3 16:10:01 hadoop-node-31 kernel:  
14.505618 Apr  3 16:10:01 hadoop-node-31 kernel: Call Trace:
15.505619 Apr  3 16:10:01 hadoop-node-31 kernel:  [<ffffffff800c9d3a>] out_of_memory+0x8e/0x2f3
16.505620 Apr  3 16:10:01 hadoop-node-31 kernel:  [<ffffffff8002dfd7>] __wake_up+0x38/0x4f
17.505621 Apr  3 16:10:01 hadoop-node-31 kernel:  [<ffffffff800a2e5d>] autoremove_wake_function+0x0/0x2e
18.505622 Apr  3 16:10:01 hadoop-node-31 kernel:  [<ffffffff8000f677>] __alloc_pages+0x27f/0x308
19.505623 Apr  3 16:10:01 hadoop-node-31 kernel:  [<ffffffff80008ead>] __handle_mm_fault+0x73e/0x103b
20.505624 Apr  3 16:10:01 hadoop-node-31 kernel:  [<ffffffff800671f2>] do_page_fault+0x499/0x842
21.505625 Apr  3 16:10:01 hadoop-node-31 kernel:  [<ffffffff8002925e>] do_brk+0x1c7/0x274
22.505626 Apr  3 16:10:01 hadoop-node-31 kernel:  [<ffffffff8005dde9>] error_exit+0x0/0x84


按服务层级来剥洋葱：

第一步，首先我们可以确定的是，肯定是hadoop自身引起的故障。

第二步，看到task java 7437吗，明显是一个java进程引发的故障，hadoop里面datanode只负责存储，很难让他发生系统崩溃级的故障，那么只可能是tasktracker进程fork出的map或者reduce进程，也就是说这个进程只可能是map或者reduce。

第三步，继续剥到505616行的时候，洋葱剥开了，终于可以流泪了，看的眼睛太干了。看到python invoked了一个 oom-killer了吧，下面紧接着就是系统调用了out_of_memory，紧接这条错误，就是kernel dump了meminfo，然后服务器就重启了。看来基本可以确定是由某一个python脚本在执行map/reduce的时候引发了服务器崩溃。

注：oom-killer是linux kernel的机制，发生内存溢出，会尝试调用vm.oom-killer将溢出程序杀死，这个可以在sysctl中设置禁用。初步判断是由于kernel尝试杀死溢出进程，hadoop又会重新调用，陷入死循环。最后节点不响应，将故障转移到其他服务器，然后其他服务器也同样处理，引发连锁反应，集群崩溃。

正常的定时mapreduce任务都是久经考验的，绝对忠诚的战士，从来没有发生过崩溃事件，所以只有可能是某人独自运行的python脚本。

问了一下同事，有一个同事在大约4点左右执行了一个跑协同过滤的脚本，脚本里可能有个大字典直接读入内存，占用内存较多，结果hadoop就OOM崩溃了。

重启以后，清理了mrlocal下面的dist-cache，很快就恢复服务了。

这里不说人，其实发生故障是好事，有点小毛病发生总比憋着一次全挂了强，记录下来的是个找故障的思路。要善用linux自带的strace,lsof,systat这些工具，也要善于读syslog，如果都指着看log4j，那可能永远也找不出故障原因。log4j所处的服务层级决定他无法完成更底层的日志记录。

另外一个好处，顺便把出故障的旧节点全统一换成EasyHadoop了。之前都是手工用tar包安装的，没法界面化管理。

还有一个好玩的事情，集群挂掉以后，剩下存活的服务器，会大量复制文件块，结果就是所有节点的网络带宽飙升。然后直到现在，各节点在重新做块平衡，大量CPU时间都被占用在IOWait上。



第二个故障是datanode重启时间不长后就挂掉了，日志显示如下


01.2013-04-04 00:37:22,842 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Receiving block blk_-145226050820856206_12015772 src=\'#\'" /192.168.1.51:9879 dest: /192.168.1.51:50010
02.at java.lang.Thread.run(Thread.java:662)
03.at org.apache.hadoop.hdfs.server.datanode.DataXceiver.run(DataXceiver.java:107)
04.at org.apache.hadoop.hdfs.server.datanode.DataXceiver.writeBlock(DataXceiver.java:299)
05.at org.apache.hadoop.hdfs.server.datanode.BlockReceiver.(BlockReceiver.java:99)
06.at org.apache.hadoop.hdfs.server.datanode.FSDataset.writeToBlock(FSDataset.java:1402)
07.org.apache.hadoop.hdfs.server.datanode.BlockAlreadyExistsException: Block blk_2613577836754795446_11189945 is valid, and cannot be written to.
08.
09.----
10.
11.************************************************************/
12.SHUTDOWN_MSG: Shutting down DataNode at hadoop-node-51/192.168.1.51
13./************************************************************
14.2013-04-04 00:43:36,872 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: SHUTDOWN_MSG:  
15.2013-04-04 00:43:34,336 INFO org.apache.hadoop.hdfs.server.datanode.DataNode: Exiting Datanode
16.2013-04-04 00:43:33,082 INFO org.apache.hadoop.hdfs.server.datanode.DataNode.clienttrace: src=\'#\'" /192.168.1.51:50010, dest: /192.168.1.46:17879, bytes: 6175632, op: HDFS_READ, cliID: DFSClient_1354167993, offset: 0, srvID: DS-1881855868-192.168.1.51-50010-1338289396565, blockid: blk_890732859468346910_12015888, duration: 21544233000
17.java.lang.OutOfMemoryError: GC overhead limit exceeded
18.2013-04-04 00:43:29,975 ERROR org.apache.hadoop.hdfs.server.datanode.DataNode: DatanodeRegistration(192.168.1.51:50010, storageID=DS-1881855868-192.168.1.51-50010-1338289396565, infoPort=50075, ipcPort=50020):DataXceiver


上半部分的错误日志累计多了之后，datanode会OOM而shutdown。

一开始看了源码里面的DataXceiver.java，DataNode.java但是没找到有用的东西，然后日志里有一个FSDataset.java，和专门抛异常的BlockAlreadyExistsException.java找到了有用的东西。

FSDataset.java里面包含了这一段
01.if (isValidBlock(b)) {
02.      if (!isRecovery) {
03.        throw new BlockAlreadyExistsException("Block " + b + " is valid, and cannot be written to.");
04.      }
05.      // If the block was successfully finalized because all packets
06.      // were successfully processed at the Datanode but the ack for
07.      // some of the packets were not received by the client. The client  
08.      // re-opens the connection and retries sending those packets.
09.      // The other reason is that an "append" is occurring to this block.
10.      detachBlock(b, 1);
11.    }


而BlockAlreadyExistsException.java里面包含这一段，其实也就这一段
01.class BlockAlreadyExistsException extends IOException {
02.  private static final long serialVersionUID = 1L;
03.
04.  public BlockAlreadyExistsException() {
05.    super();
06.  }
07.
08.  public BlockAlreadyExistsException(String msg) {
09.    super(msg);
10.  }
11.}


应该原因是因为宕机，恢复后要保证3份复制，就把其他节点上的块写入到这个节点，但是这个节点上块已经存在了，要做recover或者delete，datanode会对已经存在的blk先判断权限。然后进到存储路径下查看，有些blk的权限是664，有些则是644，644则无法recover或者delete。于是把644的改为664，就不再报这个错误，或者把644的块写脚本删除也可以。至于怎么产生的644权限文件，还没弄明白。异常抛多了，GC不能快速回收内存，DN就OOM了。不过，正常的块文件和块meta的权限应该是664，而datanode自己哈希出来的subdir，权限应该都是775，subdir下面的块应该也是664。然后调大hadoop-env.sh里面的HADOOP_HEAPSIZE和HADOOP_CLIENT_OPTS的内存数值。



另外记录关于一个hive的事，最近别的部门用phpHiveAdmin查询数据的人总跑过来说半天不出结果，也没有进度。翻看了一下Hive的配置文件，这事是这样，hive 0.10.0为了执行效率考虑，简单的查询，就是只是select，不带count,sum,group by这样的，都不走map/reduce，直接读取hdfs文件进行filter过滤。这样做的好处就是不新开mr任务，执行效率要提高不少，但是不好的地方就是用户界面不友好，有时候数据量大还是要等很长时间，但是又没有任何返回。

改这个很简单，在hive-site.xml里面有个配置参数叫

hive.fetch.task.conversion

将这个参数设置为more，简单查询就不走map/reduce了，设置为minimal，就任何简单select都会走map/reduce。

重温战场

帮你顶下哈！！

jiaxp

只是爱过不是还爱。

samsungsamsung

你都好意思和我分手，我有什么不好意思在你背后给你一刀呢

qns_fengyusong

如果爱上你只是一个梦境醒来后又该如何重新睡去