用perf给Hadoop画CPU火焰图和IO热力图

perf自带的分析结果查看方式主要是tui,这种查看方式是在终端下进行查看。Brendan Gregg大神写了几个Perl脚本,可以将perf的结果转换成更直观的火焰图和热力图,本文以Hadoop的HDFS为例介绍如何以更直观的方式查看perf的分析结果。

1. 安装aliperf和taobao-jdk

1
2
sudo yum install aliperf -btest -y
sudo yum install taobao-jdk -y

因为要分析的是Java程序,只有aliperf和taobao-jdk配合才能解析出JIT符号,不然查看perf的分析结果时,看不到Java代码中对应的方法和类。

2. 修改JVM启动参数

本文用到的Hadoop是社区的trunk版本,要在${HADOOP_HOME}/etc/hadoop-env.sh修改${HADOOP_NAMENODE_OPTS}${HADOOP_DATANODE_OPTS}这两个变量,让JVM启动时带上libjvmti_perf.so这个插件,如下所示,修改完后重启运行perf的机器上的NameNode和DataNode。

1
2
export HADOOP_NAMENODE_OPTS="-Dhadoop.security.logger=${HADOOP_SECURITY_LOGGER:-INFO,RFAS} -Dhdfs.audit.logger=${HDFS_AUDIT_LOGGER:-INFO,NullAppender} -agentpath:/usr/libexec/perf-core/libs/libjvmti_perf.so -XX:+UseOprofile $HADOOP_NAMENODE_OPTS"
export HADOOP_DATANODE_OPTS="-Dhadoop.security.logger=ERROR,RFAS -agentpath:/usr/libexec/perf-core/libs/libjvmti_perf.so -XX:+UseOprofile $HADOOP_DATANODE_OPTS"

3. 画CPU火焰图

先把Brendan Gregg大神的FlameGraph脚本下载下来

1
2
git clone git@github.com:brendangregg/FlameGraph.git
cd FlameGraph

执行HDFS的TestDFSIO压测下,让DataNode有点动静

1
hadoop jar ${HADOOP_HOME}/share/hadoop/mapreduce/hadoop-mapreduce-client-jobclient-2.4.0-tests.jar TestDFSIO -read -nrFiles 100 -size 1000MB -resFile ./logs/write.result

然后开启perf分析下DataNode,这里11691是DataNode的进程ID。

1
perf record -a -g -p 11691

等到TestDFSIO运行完成后,可以看到当前目录下面已经有perf.data这个文件,这时候用perf report --stdio已经可以直接查看结果。但是如果需要查看火焰图的话,需要再对perf.data做下转换。

1
perf script | ./stackcollapse-perf.pl | ./flamegraph.pl >perf.svg

执行上面的命令后,把perf.svg搞到本地后,用浏览器打开就可以看到类似下面的结果。实际上生成的是svg,所以鼠标移上去左下角会显示完整的Java方法名。但由于下图只是截屏,所以没法体验到这效果
TestDFSIO火焰图

4. 画IO热力图

步骤很类似,把Brendan Gregg大神的HeatMap脚本下载下来

1
2
git clone git@github.com:brendangregg/HeatMap.git
cd HeatMap

执行HDFS的TestDFSIO压测下,让DataNode有点动静

1
hadoop jar ${HADOOP_HOME}/share/hadoop/mapreduce/hadoop-mapreduce-client-jobclient-2.4.0-tests.jar TestDFSIO -read -nrFiles 100 -size 1000MB -resFile ./logs/write.result

然后开启perf分析下DataNode磁盘IO事件,这里block_rq_issu是发出IO请求时的事件,block_rq_complete是IO请求处理结束时的事件,11691是DataNode的进程ID,会统计DataNode发出IO请求到操作系统处理完IO请求的时间。

1
perf record -e block:block_rq_issue -e block:block_rq_complete -a

等到TestDFSIO运行完成后,可以看到当前目录下面已经有perf.data这个文件,执行如下命令生成IO热力图。

1
2
perf script | awk '{ gsub(/:/, "") } $5 ~ /issue/ { ts[$6, $10] = $4 } $5 ~ /complete/ { if (l = ts[$6, $9]) { printf "%.f %.f\n", $4 * 1000000, ($4 - l) * 1000000; ts[$6, $10] = 0 } }' > out.lat_us
./trace2heatmap.pl --unitstime=us --unitslat=us --stepsec=40 --maxlat=100000 out.lat_us > out.svg

执行上面的命令后,把out.svg搞到本地后,用浏览器打开就可以看到类似下面的结果。横坐标是时间轴,单位由上面的--stepsec参数指定,纵坐标是IO操作的延迟时间,单位由上面的--unitstime参数指定,上限由--maxlat指定,由于TestDFSIO指定运行时间较短,所以perf搜集到的IO操作并不是那么多,如果运行的时间更长的话,生成的热力图会更加壮观。生成的是svg,所以鼠标移上去左下角会显示每个点的具体含义。但由于下图只是截屏,所以没法体验到这效果。
TestDFSIO热力图

5. 结束

perf是个很强大的工具,Brendan Gregg大神的这几个脚本可以让我们更直观地查看perf的分析结果。不过怎么结合这些分析结果改进程序的性能,还是需要对程序的代码足够了解才能有的放矢地进行改进。