当时的状况是,下午16点左右,集群处于比较繁忙的状态,突然集群数台服务器崩溃,已经无法ssh远程连接服务器,只好找ops重启服务器,然 后就是正常的重启datanode和tasktracker。先恢复起来,再去看log,但是去看hadoop log的时候就心寒了。因为直接关电源重启,hadoop log没有任何错误记录。应该来说,只是记录到INFO,没有记录到故障就死锁,然后就重启了,所以log4j没有记录下任何信息,log4j在架构里处 于比较高的层级太高端了。只能记应用存活以前的log。应用挂了,log4j也没有存活的理由了。所以,没办法,去看syslog。
数台机器的syslog也只记录到系统重启以前的正常状态,死锁后的状态完全没有。只在一台服务器的syslog奇妙的捕获到了异常。
- 505605 Apr 3 15:59:43 hadoop-node-31 kernel: INFO: task java:7437 blocked for more than 120 seconds.
- 505606 Apr 3 15:59:55 hadoop-node-31 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
- 505607 Apr 3 15:59:55 hadoop-node-31 kernel: java D ffff810290cab860 0 7437 1 7484 7383 (NOTLB)
- 505608 Apr 3 15:59:55 hadoop-node-31 kernel: ffff8104a0f51e18 0000000000000086 0000000000001d0d 0000000000007500
- 505609 Apr 3 15:59:55 hadoop-node-31 kernel: 00000000ffffffda 000000000000000a ffff8105638cb100 ffff810290cab860
- 505610 Apr 3 15:59:56 hadoop-node-31 kernel: 001806cf1be0ca78 000000000001246f ffff8105638cb2e8 0000000300000000
- 505611 Apr 3 16:10:01 hadoop-node-31 kernel: Call Trace:
- 505612 Apr 3 16:10:01 hadoop-node-31 kernel: [<ffffffff8006467c>] __down_read+0x7a/0x92
- 505613 Apr 3 16:10:01 hadoop-node-31 kernel: [<ffffffff8006716d>] do_page_fault+0x414/0x842
- 505614 Apr 3 16:10:01 hadoop-node-31 kernel: [<ffffffff8005dde9>] error_exit+0x0/0x84
- 505615 Apr 3 16:10:01 hadoop-node-31 kernel:
- 505616 Apr 3 16:10:01 hadoop-node-31 kernel: python invoked oom-killer: gfp_mask=0x280d2, order =0, oomkilladj=0
- 505617 Apr 3 16:10:01 hadoop-node-31 kernel:
- 505618 Apr 3 16:10:01 hadoop-node-31 kernel: Call Trace:
- 505619 Apr 3 16:10:01 hadoop-node-31 kernel: [<ffffffff800c9d3a>] out_of_memory +0x8e/0x2f3
- 505620 Apr 3 16:10:01 hadoop-node-31 kernel: [<ffffffff8002dfd7>] __wake_up+0x38/0x4f
- 505621 Apr 3 16:10:01 hadoop-node-31 kernel: [<ffffffff800a2e5d>] autoremove_wake_function+0x0/0x2e
- 505622 Apr 3 16:10:01 hadoop-node-31 kernel: [<ffffffff8000f677>] __alloc_pages+0x27f/0x308
- 505623 Apr 3 16:10:01 hadoop-node-31 kernel: [<ffffffff80008ead>] __handle_mm_fault+0x73e/0x103b
- 505624 Apr 3 16:10:01 hadoop-node-31 kernel: [<ffffffff800671f2>] do_page_fault+0x499/0x842
- 505625 Apr 3 16:10:01 hadoop-node-31 kernel: [<ffffffff8002925e>] do_brk+0x1c7/0x274
- 505626 Apr 3 16:10:01 hadoop-node-31 kernel: [<ffffffff8005dde9>] error_exit+0x0/0x84
按服务层级来剥洋葱:
第一步,首先我们可以确定的是,肯定是hadoop自身引起的故障。
第二步,看到task java7437吗,明显是一个java进程引发的故障,hadoop里面datanode只负责存储,很难让他发生系统崩溃级的故障,那么只可能是tasktracker进程fork出的map或者reduce进程,也就是说这个进程只可能是map或者reduce。
第三步,继续剥到505616行的时候,洋葱剥开了,终于可以流泪了,看的眼睛太干了。看到python invoked了一个 oom-killer了吧,下面紧接着就是系统调用了out_of_memory,紧接这条错误,就是kernel dump了meminfo,然后服务器就重启了。看来基本可以确定是由某一个python脚本在执行map/reduce的时候引发了服务器崩溃。
正常的定时mapreduce任务都是久经考验的,绝对忠诚的战士,从来没有发生过崩溃事件,所以只有可能是某人独自运行的python脚本。
问了一下同事,有一个同事在大约4点左右执行了一个跑推荐算法的脚本,该脚本会读取一个150MB左右的字典,然后再把这个字典分成100份,同时跟150MB字典和hadoop上的数据做协同过滤。这就是个阶乘的关系了,结果hadoop就OOM崩溃了。
一台hadoop崩溃以后,会自动将故障转移,尝试从其他节点计算,于是引发连锁反应,结果挂掉了好几台。清理了mrlocal下面的dist-cache,很快就恢复服务了。
这里不说人,其实发生故障是好事,有点小毛病发生总比憋着一次全挂了强,记录下来的是个找故障的思路。要善用linux自带的 strace,lsof,systat这些工具,也要善于读syslog,如果都指着看log4j,那可能永远也找不出故障原因。log4j所处的服务层 级决定他无法完成更底层的日志记录。
另外一个好处,顺便把出故障的旧节点全统一换成EasyHadoop了。之前都是手工用tar包安装的,没法界面化管理。
还有一个好玩的事情,集群挂掉以后,剩下存活的服务器,会大量复制文件块,结果就是所有节点的网络带宽飙升。然后直到现在,各节点在重新做块平衡,大量CPU时间都被占用在IOWait上。
另外记录关于一个hive的事,最近别的部门用phpHiveAdmin查询数据的人总跑过来说半天不出结果,也没有进度。翻看了一下Hive的配置文件,这事是这样,hive 0.10.0为了执行效率考虑,简单的查询,就是只是select,不带count,sum,group by这样的,都不走map/reduce,直接读取hdfs文件进行where过滤。这样做的好处就是不新开mr任务,执行效率要提高不少,但是不好的地方就是用户界面不友好,有时候数据量大还是要等很长时间,但是又没有任何返回。
改这个很简单,在hive-site.xml里面有个配置参数叫
hive.fetch.task.conversion
将这个参数设置为more,简单查询就不走map/reduce了,设置为minimal,就任何简单select都会走map/reduce。