http://brandnewuser.iteye.com/blog/2144456

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

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

 

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

  1. Exception from container-launch:   

  2. org.apache.hadoop.util.Shell$ExitCodeException: /bin/bash: line 112453 已放弃                 

  3. /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  

  4.   

  5.     at org.apache.hadoop.util.Shell.runCommand(Shell.java:464)  

  6.     at org.apache.hadoop.util.Shell.run(Shell.java:379)  

  7.     at org.apache.hadoop.util.Shell$ShellCommandExecutor.execute(Shell.java:589)  

  8.     at org.apache.hadoop.yarn.server.nodemanager.DefaultContainerExecutor.launchContainer(DefaultContainerExecutor.java:195)  

  9.     at org.apache.hadoop.yarn.server.nodemanager.containermanager.launcher.ContainerLaunch.call(ContainerLaunch.java:283)  

  10.     at org.apache.hadoop.yarn.server.nodemanager.containermanager.launcher.ContainerLaunch.call(ContainerLaunch.java:79)  

  11.     at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)  

  12.     at java.util.concurrent.FutureTask.run(FutureTask.java:166)  

  13.     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)  

  14.     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)  

  15.     at java.lang.Thread.run(Thread.java:722)  




在System log中的信息为:

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

  1. #  

  2. # A fatal error has been detected by the Java Runtime Environment:  

  3. #  

  4. #  SIGSEGV (0xb) at pc=0x0000000000016996, pid=18611, tid=1097111872  

  5. #  

  6. # JRE version: 7.0_11-b21  

  7. # Java VM: Java HotSpot(TM) 64-Bit Server VM (23.6-b04 mixed mode linux-amd64 compressed oops)  

  8. # Problematic frame:  

  9. # C  0x0000000000016996  

  10. [error occurred during error reporting (printing problematic frame), id 0xb]  

  11.   

  12. # Failed to write core dump. Core dumps have been disabled. To enable core dumping, try "ulimit -c unlimited" before starting Java again  

  13. #  

  14. # An error report file with more information is saved as:  

  15. # /home/data9/hdfsdir/nm-local-dir/usercache/supertool/appcache/application_1410771599055_15737/container_1410771599055_15737_01_000099/hs_err_pid18611.log  

  16. #  

  17. # If you would like to submit a bug report, please visit:  

  18. #   http://bugreport.sun.com/bugreport/crash.jsp  

  19. #  



系统中提示的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文件保存起来,避免无意中删除该文件,经过查找找到参数:

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

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


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

 

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

  1. yarn.log-aggregation.retain-seconds=-1  

  2. 保存汇聚日志时间,秒,超过会删除,-1表示不删除。 注意,设置的过小,将导致NN垃圾碎片。建议3-7天 = 7 * 86400 = 604800  

  3. yarn.nodemanager.log.retain-seconds=10800  

  4. 保留用户日志的时间,秒。在日志汇聚功能关闭时生效。  

  5. 建议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的部分截图)


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

 


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

错误在Reduce端有3种类型:

  • 已放弃;

  • 段错误;

  • 总线错误;

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

 

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

 

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

  1. JobContext.TASK_ATTEMPT_ID(mapreduce.task.attempt.id)  

 

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