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

最新推荐文章于 2021-03-06 09:26:30 发布

aliveTime

最新推荐文章于 2021-03-06 09:26:30 发布

阅读量4.8k

点赞数

分类专栏： hadoop

本文链接：https://blog.csdn.net/aliveTime/article/details/8704805

版权

hadoop 专栏收录该内容

9 篇文章 0 订阅

订阅专栏

最近集群计算迁移, 某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("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进程内存占用