一次让人峰回路转, 颜面扫地的trouble shooting, Apache Pig

gaoke

　　最近集群计算迁移, 某Pig脚本在新集群上运行失败, 排除了文件损坏等问题, 还是每次复现失败. 日志如下:
　　
　　表面原因是FileSystem 被关闭, 难道是Pig版本代码的bug, 关闭了不该关闭的FileSystem?
　　



第一次尝试


　　带着这个思路, 写了btrace脚本跟踪DFSStream的close方法. 脚本如下:

import com.sun.btrace.annotations.*;
import static com.sun.btrace.BTraceUtils.*;
@BTrace
public class PigTrace {
@TLS
private static String jstack = null;
@OnMethod(clazz = "org.apache.pig.backend.hadoop.executionengine.physicalLayer.relationalOperators.POStore",
//
location = @Location(value = Kind.THROW))
public static void getNext() {
print(timestamp("yyyy-MM-dd HH:mm:ss.SSS"));
println("throw ===start");
println(jstack);
println("throw ===end");
}
@OnMethod(clazz = "org.apache.hadoop.hdfs.DFSOutputStream", method = "closeThreads", location = @Location(Kind.RETURN))
public static void closing() {
jstack = jstackStr();
print(timestamp("yyyy-MM-dd HH:mm:ss.SSS"));
println(jstack);
}

@OnMethod(clazz = "org.apache.hadoop.hdfs.DFSOutputStream", method = "close", location = @Location(Kind.RETURN))
public static void closeing1() {
jstack = jstackStr();
print(timestamp("yyyy-MM-dd HH:mm:ss.SSS"));
println(jstack);
}
}
　　很简单, 每次调用close方法或者closeThreads方法时. 都打印对应的jstack.
　　上线, 观察结果


　　


　　所有的关闭都是org.apache.hadoop.util.ShutdownHookManager 进行的, 也就是没有业务代码直接关闭了DFSOutputStream.
　　这里插入一个小插曲, 众所周知的btrace常用的功能就是等Java进程启动后根据PID attach到java进程. 但对于hadoop运行任务来说, 每个Task进程是随机分配到多台服务的,定位非常麻烦, 而且也不一定来得及手动attach上去. 因此推荐使用第二种方法, 在java进程启动的时候就加载javaagent的方式启动btrace, hadoop的配置如下:

        <property>
<name>mapred.map.child.java.opts</name>
<value>-Xmx1G -javaagent:/tmp/btrace/btrace-agent.jar=script=/tmp/btrace/PigTrace.class,stdout=aa.log,noServer=true</value>
</property>

其中,

　　        stdout=aa.log是重定向标准输出, 但如果不添加该选项, btrace的输出不知道跑到哪里去了. 添加了之后, btrace结果仍然会显示在hadoop任务的stdout中, 可以在jobtracker中直接查看.
　　       noServer=true是让btrace不再开启server模式. 众所周知, btrace会让目标java进程开启2020端口, 与btrace shell进行通信, 输出结果. 我们这种方式, 仅仅需要将结果输出到stdout. 如果不使用该选项,可能会出现端口被占用的错误, 如下:
　　
　　那是为什么? 难道是Task进程OOM? 但是我们的mapred.map.child.java.opts参数已经指定了OOM时dump heap, 没有任何的heap dump.


　　不会是出现某种特殊情况进程直接exit吧?



第二次尝试
　　

@OnExit
public static void onExit(int code){
println(strcat(&quot;process exit, code: &quot;,str(code)));
}

使用btrace跟踪exit调用. 打印stacktrace, 看情况如何.　　
　　上线, 结果没有任何输出. 没有exit? ? ? 那进程是如何退出的? 到底发生了什么? 不过我还是怀疑内存问题, 这次来个狠的, 直接dump 内存吧.

第三次尝试
　　

@OnTimer(60000)
public static void dumpOnTime(){
dumpHeap(strcat(&quot;/tmp/heap.&quot;, strcat(str(getpid()), strcat(&quot;.&quot;, timestamp(&quot;yyyy-MM-dd_HH.mm.ss.SSS&quot;)))));
}

每隔60s dump 一次java heap. 等任务失败后分析最后一次dump.

　　
　　小插曲, 默认情况下, btrace dump heap时必须在当前进程的目录下, 不能使用绝对路径.hadoop task的work dir 是随机分配的,dump结果很难找,
也可能被tasktracker清理. 我修改了btrace 源代码, 取消了该限制, 代码放在了github上: https://github.com/haitaoyao/btrace
　　错误如下:
　　


　　


　　再次上线, heap dump出来了. 拉回来分析, 发现结果如下:
　　
　　占用内存最多的是SpillableMemoryManager,这个类监听内存占用,如果超过一定阀&#20540;,就将监控的Spillable的数据spill到磁盘上,
减少内存占用. 可Task进程并没有OOM啊?进程也没有exit. 那为什么失败? 难道, 是被kill的?
　　可Java
的sun.misc.SignalHandler 不支持捕捉Kill 信号. OMG~~


　　

同事提醒了一声, 是不是内存超了被tasktracker kill了?
　　shit....
仔细翻log, 果然是:
　　

TaskTree [pid=22145,tipID=attempt_201303071829_3239_m_000001_0] is running beyond physical memory-limits. Current usage : 1097891840bytes. Limit : 1073741824bytes. Killing task. TaskTree [pid=22145,tipID=attempt_201303071829_3239_m_000001_0] is running beyond physical memory-limits. Current usage : 1097891840bytes. Limit : 1073741824bytes. Killing task. Dump of the process-tree for attempt_201303071829_3239_m_000001_0 :         |- PID PPID PGRPID SESSID CMD_NAME USER_MODE_TIME(MILLIS) SYSTEM_TIME(MILLIS) VMEM_USAGE(BYTES) RSSMEM_USAGE(PAGES) FULL_CMD_LINE
|- 22145 26343 22145 22145 (java) 26635 238 1689505792 268040 /usr/lib/jvm/java-1.7.0-openjdk-1.7.0.9.x86_64/jre/bin/java -Djava.library.path=/usr/lib/hadoop-0.20-mapreduce/lib/native/Linux-amd64-64:/tmp/hadoop-mapred/mapred/local/taskTracker/hadoop/jobcache/job_201303071829_3239/attempt_201303071829_3239_m_000001_0/work -Xmx1G -Djava.io.tmpdir=/tmp/hadoop-mapred/mapred/local/taskTracker/hadoop/jobcache/job_201303071829_3239/attempt_201303071829_3239_m_000001_0/

打脸! 为啥一开始没有仔细看log? !
　　
　　恍然惊醒,
在hadoop的配置如下:
　　

        <property>
<name>mapreduce.map.memory.physical.mb</name>
<value>1024</value>
</property>
<property>
<name>mapred.map.child.java.opts</name>
<value>-Xmx1G</value>
</property>

我开启了org.apache.hadoop.util.LinuxMemoryCalculatorPlugin, 当map进程超过1024MB时认为内存超限, 直接kill了task. 而给map进程设置的Heap内存是1G,可Java进程还有Off heap 内存呢, 比如PermGen等...　　
　　泪奔了...
修改了配置Heap为800MB, 一切正常...
　　附:
java进程内存占用
　　
　　转自:
http://www.ibm.com/developerworks/java/library/j-codetoheap/index.html


　　


　　一次狗屎,
峰回路转, 颜面扫地的trouble shooting....


　　


　　


　　


　　


　　





版权声明：本文为博主原创文章，未经博主允许不得转载。