MapReduce项目中的一个JVM错误问题分析和解决

最近一周都在查项目的各种问题，由于对原有的一个MapReduce分析数据的项目进行重构，减少了运行时的使用资源，但是重构完成后，在Reduce端总是不定时地抛出JVM的相关错误，非常随机，没有发现有什么特殊的规律性。

问题在Reduce的控制台显示信息：

 

Exception from container-launch: 
org.apache.hadoop.util.Shell$ExitCodeException: /bin/bash: line 1: 12453 已放弃               
/usr/java/jdk1.7.0_11//bin/java -Djava.net.preferIPv4Stack=true -Dhadoop.metrics.log.level=WARN -Xmx3072M -Djava.io.tmpdir=/home/data12/hdfsdir/nm-local-dir/usercache/supertool/appcache/application_1410771599055_15737/container_1410771599055_15737_01_000100/tmp -Dlog4j.configuration=container-log4j.properties -Dyarn.app.container.log.dir=/home/workspace/hadoop/logs/userlogs/application_1410771599055_15737/container_1410771599055_15737_01_000100 -Dyarn.app.container.log.filesize=0 -Dhadoop.root.logger=INFO,CLA org.apache.hadoop.mapred.YarnChild 192.168.7.87 29145 attempt_1410771599055_15737_r_000004_0 100 > /home/workspace/hadoop/logs/userlogs/application_1410771599055_15737/container_1410771599055_15737_01_000100/stdout 2> /home/workspace/hadoop/logs/userlogs/application_1410771599055_15737/container_1410771599055_15737_01_000100/stderr

    at org.apache.hadoop.util.Shell.runCommand(Shell.java:464)
    at org.apache.hadoop.util.Shell.run(Shell.java:379)
    at org.apache.hadoop.util.Shell$ShellCommandExecutor.execute(Shell.java:589)
    at org.apache.hadoop.yarn.server.nodemanager.DefaultContainerExecutor.launchContainer(DefaultContainerExecutor.java:195)
    at org.apache.hadoop.yarn.server.nodemanager.containermanager.launcher.ContainerLaunch.call(ContainerLaunch.java:283)
    at org.apache.hadoop.yarn.server.nodemanager.containermanager.launcher.ContainerLaunch.call(ContainerLaunch.java:79)
    at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
    at java.util.concurrent.FutureTask.run(FutureTask.java:166)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
    at java.lang.Thread.run(Thread.java:722)

在System log中的信息为：

#
# A fatal error has been detected by the Java Runtime Environment:
#
#  SIGSEGV (0xb) at pc=0x0000000000016996, pid=18611, tid=1097111872
#
# JRE version: 7.0_11-b21
# Java VM: Java HotSpot(TM) 64-Bit Server VM (23.6-b04 mixed mode linux-amd64 compressed oops)
# Problematic frame:
# C  0x0000000000016996
[error occurred during error reporting (printing problematic frame), id 0xb]

# Failed to write core dump. Core dumps have been disabled. To enable core dumping, try "ulimit -c unlimited" before starting Java again
#
# An error report file with more information is saved as:
# /home/data9/hdfsdir/nm-local-dir/usercache/supertool/appcache/application_1410771599055_15737/container_1410771599055_15737_01_000099/hs_err_pid18611.log
#
# If you would like to submit a bug report, please visit:
#   http://bugreport.sun.com/bugreport/crash.jsp
#

系统中提示的JVM dump文件并没有在那台Reduce端机器上被发现，由于Reducer会在任务执行完成后将所有文件夹及文件都清理掉，application文件夹都没有发现。

由于Java的安全性，出现内存错误也不会报上面的这种类型异常，一般是某个区域空间不足，比如Perm，Heap等。经过一轮排查，将问题锁定在Reduce端会调用的一段JNI代码上。关于JNI的基本使用，可以参考：http://brandnewuser.iteye.com/blog/2117182

将JNI的代码注释掉之后，果然问题不再重现。在重构该部分代码之前，系统并未产生过这种类型的错误，于是将调用JNI这段代码还原到以前的一个版本，发现错误仍然发生；考虑到重构前代码使用内存很大，测试时将Reducer端的Heap内存也提高到8G，同样不管用。

尝试加入-XCheck:jni=true参数，发现hadoop的压缩格式都会发生检查错误，比如SequenceFile以及Snappy压缩，程序无法进行，因此暂时还是关闭了这个参数。

同事开始对JNI使用的.so库进行多进程测试i执行，结果表明该库并不存在并发问题。

那么想办法将这个dump文件保存起来，避免无意中删除该文件，经过查找找到参数:

-Dmapreduce.task.files.preserve.failedtasks=true

参数表示保留失败的tasks相关文件，但是实际运行完成后也并没有保存，又经过查找，看到另外一个参数，设置该参数后，dump文件仍然被清除。

 

yarn.log-aggregation.retain-seconds=-1
保存汇聚日志时间，秒，超过会删除，-1表示不删除。 注意，设置的过小，将导致NN垃圾碎片。建议3-7天 = 7 * 86400 = 604800
yarn.nodemanager.log.retain-seconds=10800
保留用户日志的时间，秒。在日志汇聚功能关闭时生效。
建议7天

注：有篇文章讲Hadoop的所有使用参数，比较详细：http://segmentfault.com/blog/timger/1190000000709725

有同事说这个时yarn的参数，是否需要重新启动yarn框架（不需要重启整个map/reduce框架），果然在失败后拿到了core.dump文件！

高兴之余，C++高手用gdb对这个文件进行了详细的分析，并没有发现太多线索。

于是大家一起重新过了使用JNI的代码，果然发现了一个问题。我们在使用JNI时，将.so库打包到jar包中，在实际Reduce端运行时才会将该.so文件用文件流的方式写到当前/tmp文件夹下，这就意味着，加入多个Reduce同时运行该程序，就会导致该so文件重复写的可能。

为了验证是否这个原因导致的，我们在Reduce端开始运行时，ssh到那台机器上，用shell脚本循环重复地向该文件夹中复制so文件，该JVM错误稳定重现。（下图就是一个FAILED Reduce Task的部分截图）

 

 

仔细想了一下，为什么原来的代码中并没有出现该问题，因为原来的程序Reduce端占用比较大，并且Partition的哈希并不均匀，我们只能启动大概3个任务，出现错误的概率比较小，于是我们强制启动5个任务，果然发生了一个Reduce端出现了错误。

错误在Reduce端有3种类型：

• 已放弃；
• 段错误；
• 总线错误；

但原因都是一致的，在JNI执行调用时，库文件被莫名地替换掉了，导致无法找到该内存地址的数据（猜测），从而导致段错误等内存地址错误(SEGSEGV)的发生。

 

于是我们马上改代码，更改的思路，是在map/reduce任务中，Task的AttempID总是唯一的，于是考虑将每个任务的.so本地库文件进行了文件夹隔离，通过运行时的JobConf参数获得：

 

JobContext.TASK_ATTEMPT_ID（mapreduce.task.attempt.id）

 

于是，问题便顺利地解决再也不重现了，但需要在Reduce端执行完成后，将该文件夹的数据进行清理操作。可是如果任务是被Container kill或是自己Fail掉的，并不会得到清理，需要写脚本确保在没有任务执行时将集群中的文件夹清理。

评论

2 楼 brandNewUser 2014-11-19  

zongquanliu 写道

我也遇到了这个问题，原因应该就是你剖析的，真是省了大事了，哈哈！

很高兴对你有帮助，当时这个问题也是耗费了我们很大的精力想尽各种办法才最终解决的，希望都能跳过这些坑

1 楼 zongquanliu 2014-11-18  

我也遇到了这个问题，原因应该就是你剖析的，真是省了大事了，哈哈！