hadoop中使用hprof工具进行性能分析
在编写完成MapReduce程序之后，调优就成为了一个大问题。如何使用现有工具快速地分析出任务的性能？
对于本地的java应用程序，进行分析可能稍微简单，但是hadoop是一个分布式框架，MapReduce任务可能在集群中的任意机器上被调度运行。而且本地Job运行器是一个与集群差异非常大的环境，数据流的形式也不同，应该在实际集群上对比新的执行时间和旧的执行时间。
hadoop的任务中可以选择启用profile，这可以在特定的Map/Reduce任务启动执行hprof分析。prof是一个JDK自带的分析工具，虽然只有基本功能，但是同样能够提供程序CPU运行和堆使用情况等相关的有用信息。
经过半天的摸索，大概使用方法介绍一下，所有的参数如下：
Option Name and Value Description Default --------------------- ----------- ------- heap=dump|sites|all heap profiling all cpu=samples|times|old CPU usage off monitor=y|n monitor contention n format=a|b text(txt) or binary output a file=<file> write data to file java.hprof[.txt] net=<host>:<port> send data over a socket off depth=<size> stack trace depth 4 interval=<ms> sample interval in ms 10 cutoff=<value> output cutoff point 0.0001 lineno=y|n line number in traces? y thread=y|n thread in traces? n doe=y|n dump on exit? y msa=y|n Solaris micro state accounting n force=y|n force output to <file> y verbose=y|n print messages about dumps y
CPU使用分析
cpu=samples
hprof工具通过抽样分析（定时）线程可以收集所有的运行线程，记录最频繁的StackTraces，官网上给出的例子，通过javac来进行性能分析：
Command used: javac -J-agentlib:hprof=cpu=samples Hello.java CPU SAMPLES BEGIN (total = 126) Fri Oct 22 12:12:14 2004 rank self accum count trace method 1 53.17% 53.17% 67 300027 java.util.zip.ZipFile.getEntry 2 17.46% 70.63% 22 300135 java.util.zip.ZipFile.getNextEntry 3 5.56% 76.19% 7 300111 java.lang.ClassLoader.defineClass2 4 3.97% 80.16% 5 300140 java.io.UnixFileSystem.list 5 2.38% 82.54% 3 300149 java.lang.Shutdown.halt0 6 1.59% 84.13% 2 300136 java.util.zip.ZipEntry.initFields 7 1.59% 85.71% 2 300138 java.lang.String.substring 8 1.59% 87.30% 2 300026 java.util.zip.ZipFile.open 9 0.79% 88.10% 1 300118 com.sun.tools.javac.code.Type$ErrorType.<init> 10 0.79% 88.89% 1 300134 java.util.zip.ZipFile.ensureOpen
count代表一个特定的StackTrace被采样的次数，而不是方法真实被调用了几次。这个选项不需要字节码注入，也不需要修改ClassLoader，不会对程序的正常执行造成多大的干扰。
cpu=times
hprof工具还可以通过字节码注入的方式分析每个方法的入口和出口，保存具体方法的调用次数和时间消耗，同样也会带来性能的消耗，比上一种方式要慢很多。
Command used: javac -J-agentlib:hprof=cpu=times Hello.java CPU TIME (ms) BEGIN (total = 103099259) Fri Oct 22 12:21:23 2004 rank self accum count trace method 1 5.28% 5.28% 1 308128 com.sun.tools.javac.Main.compile 2 5.16% 10.43% 1 308127 com.sun.tools.javac.main.Main.compile 3 5.15% 15.58% 1 308126 com.sun.tools.javac.main.Main.compile 4 4.07% 19.66% 1 308060 com.sun.tools.javac.main.JavaCompiler.compile 5 3.90% 23.56% 1 306652 com.sun.tools.javac.comp.Enter.main 6 3.90% 27.46% 1 306651 com.sun.tools.javac.comp.Enter.complete 7 3.74% 31.21% 4 305626 com.sun.tools.javac.jvm.ClassReader.listAll 8 3.74% 34.95% 18 305625 com.sun.tools.javac.jvm.ClassReader.list 9 3.24% 38.18% 1 305831 com.sun.tools.javac.comp.Enter.classEnter 10 3.24% 41.42% 1 305827 com.sun.tools.javac.comp.Enter.classEnter 11 3.24% 44.65% 1 305826 com.sun.tools.javac.tree.Tree$TopLevel.accept
这里的数据count代表了方法进入的真实次数。
Heap内存分析
heap=sites
hprof工具还可以打印出Java堆的相关对象信息。
下面的SITES纪录告诉我们最多的ZipEntry对象在一个特定的Site下，占用44%的总内存。
Command used: javac -J-agentlib:hprof=heap=sites Hello.java
SITES BEGIN (ordered by live bytes) Fri Oct 22 11:52:24 2004
percent live alloc'ed stack class
rank self accum bytes objs bytes objs trace name
1 44.73% 44.73% 1161280 14516 1161280 14516 302032 java.util.zip.ZipEntry
2 8.95% 53.67% 232256 14516 232256 14516 302033 com.sun.tools.javac.util.List
3 5.06% 58.74% 131504 2 131504 2 301029 com.sun.tools.javac.util.Name[]
4 5.05% 63.79% 131088 1 131088 1 301030 byte[]
5 5.05% 68.84% 131072 1 131072 1 301710 byte[]
还会打印如下的堆栈信息：
TRACE 302032:
java.util.zip.ZipEntry.<init>(ZipEntry.java:101)
java.util.zip.ZipFile$3.nextElement(ZipFile.java:435)
java.util.zip.ZipFile$3.nextElement(ZipFile.java:413)
com.sun.tools.javac.jvm.ClassReader.openArchive(ClassReader.java:1442)
TRACE 302033:
com.sun.tools.javac.util.List.<init>(List.java:43)
com.sun.tools.javac.util.List.<init>(List.java:51)
com.sun.tools.javac.util.ListBuffer.append(ListBuffer.java:98)
com.sun.tools.javac.jvm.ClassReader.openArchive(ClassReader.java:1442)
每个栈帧都包含了类型名称，方法名称和行号，用户可以通过depth设置栈的深度（默认是4），堆栈信息揭露了哪些方法触发了堆内存分配。
heap=dump
如果想得到一个大而全的当前堆活动对象，可以使用这个选项，但是这会导致一个巨大的输出文件。
分析源码并使用
在hadoop的源码中，方法中指定了profile的使用：
org.apache.hadoop.mapred.MapReduceChildJVM
public static List<String> getVMCommand(InetSocketAddress taskAttemptListenerAddr,
Task task,
ID jvmID)
if (conf.getProfileEnabled()) {
if (conf.getProfileTaskRange(task.isMapTask()
).isIncluded(task.getPartition())) {
vargs.add(
String.format(
conf.getProfileParams(),
getTaskLogFile(TaskLog.LogName.PROFILE)
)
);
if (task.isMapTask()) {
vargs.add(conf.get(MRJobConfig.TASK_MAP_PROFILE_PARAMS, ""));
}
else {
vargs.add(conf.get(MRJobConfig.TASK_REDUCE_PROFILE_PARAMS, ""));
}
}
}
hadoop任务中可以通过编码来设置profile：
conf.setProfileEnabled(true); conf.setProfileParams(…); conf.setProfileTaskRange...
也可以通过设置参数：
- mapreduce.task.profile=true，可以设置profile enabled状态，开启profile模式；
- mapreduce.task.profile.maps=0-2，我们不可能将所有map都进行profile，profile是非常消耗资源的(事实上能够看出使用profile的map/reduce执行速度明显变慢)，不建议在生产环境中使用profiler，那么使用这个参数就可以指定执行profile的part；
- mapreduce.task.profile.reduces=0-2，同上；
- mapreduce.task.profile.params，指定profile的选项，默认值：-agentlib:hprof=cpu=samples,heap=sites,force=n,thread=y, verbose=n,file=%s，
最后的profiler文件放在<LOG_DIR>中，与stderr, stdout在同文件夹，名称为profile.out
hadoop jar命令中加入如下的参数：
-Dmapreduce.task.profile=true -Dmapreduce.task.profile.params="-agentlib:hprof=cpu=samples,heap=dump,force=y,interval=100,thread=y,verbose=n,file=%s"
经过实验采样分析后的CPU指数:
CPU SAMPLES BEGIN (total = 62259) Wed Nov 19 14:49:57 2014 rank self accum count trace method 1 34.01% 34.01% 21173 300882 sun.nio.ch.EPollArrayWrapper.epollWait 2 6.02% 40.02% 3746 301467 com.xxx.Counter.update 3 5.65% 45.68% 3518 301353 java.lang.String.split 4 2.66% 48.34% 1656 301358 java.lang.Double.parseDouble 5 2.28% 50.62% 1422 301240 java.io.FileInputStream.readBytes 6 2.27% 52.89% 1414 301354 java.lang.Double.parseDouble 7 2.08% 54.97% 1292 301349 java.util.HashMap.hash 8 2.07% 57.04% 1291 301346 sun.nio.cs.UTF_8$Decoder.decodeArrayLoop 9 1.35% 58.39% 842 301373 java.util.HashMap.hash 10 0.98% 59.37% 611 301364 org.apache.hadoop.io.compress.snappy.SnappyDecompressor.decompress
考虑到使用cpu=times时，使用字节码增强技术可能导致计算量增大，MR任务可能出现超时的情况（超时的日志如下，表明TaskTracker可能一段时间内没有向JobTracker发送必要的信息），如果进行测试工作，可以将超时参数暂时设置得稍大一点，以避免这种情况。
AttemptID:attempt_1413206225298_36800_m_000000_1 Timed out after 1200 secs
