查看hadoop启动的日志命令查看hadoop中log日志

转载

mob64ca1419e0cc 2024-02-05 05:06:43

文章标签 查看hadoop启动的日志命令大数据 java python hadoop 文章分类 Hadoop 大数据

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

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

数台机器的syslog也只记录到系统重启以前的正常状态，死锁后的状态完全没有。只在一台服务器的syslog奇妙的捕获到了异常。

1. 505605 Apr  3 15:59:43 hadoop-node-31 kernel: INFO: task java:7437 blocked for
2. 505606 Apr  3 15:59:55 hadoop-node-31 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
3. 505607 Apr  3 15:59:55 hadoop-node-31 kernel: java          D ffff810290cab860     0  7437      1          7484  7383 (NOTLB) 
4. 505608 Apr  3 15:59:55 hadoop-node-31 kernel:  ffff8104a0f51e18 0000000000000086 0000000000001d0d 0000000000007500 
5. 505609 Apr  3 15:59:55 hadoop-node-31 kernel:  00000000ffffffda 000000000000000a ffff8105638cb100 ffff810290cab860 
6. 505610 Apr  3 15:59:56 hadoop-node-31 kernel:  001806cf1be0ca78 000000000001246f ffff8105638cb2e8 0000000300000000 
7. 505611 Apr  3 16:10:01 hadoop-node-31 kernel: Call Trace: 
8. 505612 Apr  3 16:10:01 hadoop-node-31 kernel:  [<ffffffff8006467c>] __down_read+0x7a/0x92 
9. 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重启时间不长后就挂掉了，日志显示如下

1. 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 
2. at
3. at
4. at
5. at
6. at
7. org.apache.hadoop.hdfs.server.datanode.BlockAlreadyExistsException: Block blk_2613577836754795446_11189945 is valid, and cannot be written to. 
8.  
9. ----
10.  
11. ************************************************************/ 
12. SHUTDOWN_MSG: Shutting down DataNode at
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里面包含了这一段

1. if
2. if
3. throw new BlockAlreadyExistsException("Block " + b + " is valid, and cannot be written to."); 
4.       } 
5. // If the block was successfully finalized because all packets
6. // were successfully processed at the Datanode but the ack for
7. // some of the packets were not received by the client. The client 
8. // re-opens the connection and retries sending those packets.
9. // The other reason is that an "append" is occurring to this block.
10. 1); 
11.     }

而BlockAlreadyExistsException.java里面包含这一段，其实也就这一段

1. class BlockAlreadyExistsException extends
2. private static final long
3.  
4. public
5. super(); 
6.   } 
7.  
8. public
9. 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。

本文章为转载内容，我们尊重原作者对文章享有的著作权。如有内容错误或侵权问题，欢迎原作者联系我们进行内容更正或删除文章。