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

最近集群计算迁移, 某Pig脚本在新集群上运行失败, 排除了文件损坏等问题, 还是每次复现失败. 日志如下:

表面原因是FileSystem 被关闭, 难道是Pig版本代码的bug, 关闭了不该关闭的FileSystem?

第一次尝试

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

import com.sun.btrace.annotations.*;import static com.sun.btrace.BTraceUtils.*;@BTracepublic class PigTrace {@TLSprivate 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吧?

第二次尝试

@OnExitpublic static void onExit(int code){println(strcat("process exit, code: ",str(code)));}

使用btrace跟踪exit调用. 打印stacktrace, 看情况如何.

上线, 结果没有任何输出. 没有exit? ? ? 那进程是如何退出的? 到底发生了什么? 不过我还是怀疑内存问题, 这次来个狠的, 直接dump 内存吧.

第三次尝试

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

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

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

错误如下:

再次上线, heap dump出来了. 拉回来分析, 发现结果如下:

占用内存最多的是SpillableMemoryManager,这个类监听内存占用,如果超过一定阀值,就将监控的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....