ablog

不器用で落着きのない技術者のメモ

Java Mixed-Mode Flame Graphs で Java の CPU ネックをフルスタックで分析する

Java Linux

Brendan Gregg (NETFLIX の Senior Performance Architect) 作の Java Mixed-Mode Flame Graphs を使うと Java のプロセスが CPU ネックのケースで、Java アプリケーションコード、JVM(HotSpot VM)、Linux Kernel のどのレイヤーのどの関数がボトルネックになっているかを簡単に特定することができます。
以下は GitHub - martint/jittest: Demonstrate JIT compiler issue in java 7 のワークロードを実行して Flame Graphs で可視化したものです。

以下は Java One 2015 での Brendan Gregg のスライドです(YouTube もあります)。

「Brendan Gregg って誰？」「Flame Graphs って何？」という方は以下のエントリをご覧ください。

Flame Graphs は perf(Linux)、SystemTap(Linux)、DTrace(Solaris、Oracle Linux(UEK)、Mac OS X、FreeBSD)、XPerf.exe(Windows) などでのプロファイリング結果を可視化して最も使われているコードパスを早く正確に特定することができます。実体はプロファイリング結果をグラフ(SVG)に変換する Perl スクリプトです。

下から上に行くほどコールスタックが深く、左から関数名のアルファベット順でソートされています。一番上で横幅が広い関数がCPUを長く使っています。


作者の Brendan Gregg は Sun、Oracle、Joyent でカーネル、パフォーマンスのエンジニアとして活躍し、現在は Netflix(北米のインターネットのトラフィックの32.3%を占める。YouTubeは17.1%) のシニア・パフォーマンス・アーキテクトです。ZFS L2ARC や DTrace Toolkit の開発者で、Solaris Performance and Tools、DTrace: Dynamic Tracing in Oracle Solaris, Mac OS X and FreeBSD の著者で、LinuxCon、FreeBSD Summit、Oaktable World、AWS re:Invent などのイベントで幅広く活動されています。

perf + Flame Graphs で Linux カーネル内のボトルネックを特定する - ablog

まとめ

  • JDK 8u60 build 19 以降(JDK-8072465 が含まれる)または JDK 9(JDK-8068945 が含まれる) で、
  • -XX:+PreserveFramePointer を指定して Java を実行し、
java -XX:+PreserveFramePointer ...
  • Perf でプロファイリングし、
perf record -F 99 -a -g -- sleep 30

java -cp attach-main.jar:$JAVA_HOME/lib/tools.jar net.virtualvoid.perf.AttachOnce <PID>

chown root /tmp/perf-*.map
  • FlameGraph で SVG にすると、
perf script|stackcollapse-perf.pl|flamegraph.pl --color=java --hash > flamegraph_java.svg
  • Java アプリケーションコード、JVM、Linux Kernel のどのレイヤーのどの関数がCPUを最も使っているか一目でわかる

背景・経緯

サマリ
  • Java Profiler(hprof などは Java のメソッドしかプロファイリングできない) と System Profiler(Perf などは Linux Kernel や HotSpot をプロファイリングできるが Java のメソッドをプロファイリングできない) はカバー範囲が違うため、Java のプロセスの CPU ネックの原因を特定するには Java Profiler と System Profiler の両方を見る必要があった。 以下の2つの問題点に対応し、System Profiler で全範囲をカバーできるようになった。
HotSpot のレジスタの使い方の問題
JIT コンパイルされたメソッドのシンボルテーブルの問題
  • JVM が JIT コンパイルしたメソッドは Perf のような System Profiler が使うシンボルテーブルに出ないため JIT コンパイルされたメソッドを取得できない。
  • Johannes Rudolph 作の perf-map-agent で Java のプロセスにアタッチすると取得できる。

必要なソフトウェア

環境セットアップ

Java 8 update 60 build 19 以降をダウンロード
$ cd ~/Downloads/bin
$ tar xfvz jdk-8u102-ea-bin-b04-linux-x64-25_apr_2016.tar.gz 
$ cd jdk1.8.0_102/bin
$ ./java -version
java version "1.8.0_102-ea"
Java(TM) SE Runtime Environment (build 1.8.0_102-ea-b04)
Java HotSpot(TM) 64-Bit Server VM (build 25.102-b04, mixed mode)
perf-map-agent をダウンロード・インストール
$ su -
# yum install cmake
# exit
$ cd ~/Documents/github
$ git clone --depth=1 https://github.com/jrudolph/perf-map-agent
$ cd perf-map-agent
$ cmake .
$ make
FlameGraph をダウンロード
$ cd ~/Documents/github
$ git clone --depth=1 https://github.com/brendangregg/FlameGraph

テストケース準備

このテストケースは Flame Graphs とは関係ありません。分析対象として実行する Java コードとして、Javaの謎のパフォーマンス劣化現象との戦い - Cybozu Inside Out | サイボウズエンジニアのブログ で紹介されている GitHub - martint/jittest: Demonstrate JIT compiler issue in java 7 を実行するためのセットアップ手順です。

  • maven をダウンロード・インストールする
$ cd ~/Downloads/bin
$ curl -L -O http://ftp.jaist.ac.jp/pub/apache/maven/maven-3/3.3.9/binaries/apache-maven-3.3.9-bin.tar.gz
$ tar xfvz apache-maven-3.3.9-bin.tar.gz
$ mv apache-maven-3.3.9 /opt/

$ cd ~/Documents/github
$ git clone https://github.com/martint/jittest.git
$ cd jittest
$ export PATH=$PATH:/opt/apache-maven-3.3.9/bin
$ mvn install

テストケース実行

$ cd ~/Documents/github/jittest
$ export JAVA_HOME=~/Downloads/bin/jdk1.8.0_102
$ export PATH=~/Downloads/bin/jdk1.8.0_102/bin:$PATH
$ java -XX:+PreserveFramePointer -XX:ReservedCodeCacheSize=20m -XX:InitialCodeCacheSize=20m \
 -jar target/jittest-1.0-SNAPSHOT-standalone.jar > jittest.log &
[1] 9144 ★ PID は 9144
$ head -5 jittest.log
Timestamp	Compilation Time	Code Cache Size	Perm Gen/Metaspace Size	Invocations/s
1462677134771	972	2856960	4895984	27.40
1462677135775	2079	4200320	5560072	54.12
1462677136776	3192	5443200	5965504	75.44
1462677137776	4242	5320640	6329632	93.29
  • perf-map-agent を実行する(テストケース実行中に)
$ cd ~/Documents/github/perf-map-agent
$ java -cp ~/Documents/github/perf-map-agent/out/attach-main.jar:$JAVA_HOME/lib/tools.jar \
 net.virtualvoid.perf.AttachOnce 9144 #9144 は Java の PID

Perf + Flame Graph で可視化する

  • Perf でプロファイリングする(テストケース実行中に)
$ su -
# perf record -F 99 -a -g -- sleep 30
  • Flame Graph で可視化する(perf-map-agent 実行後に実行する)
# chown root /tmp/perf-*.map
# perf script |perl stackcollapse-perf.pl |\
 perl flamegraph.pl --title "OpenJDK 8u102 Build b04, Mixed Mode CPU Flame Graph: green == Java, yellow == C++, red == system"\
 --color=java --hash > flamegraph_java.svg

flamegraph_java.svg が本エントリの冒頭のイメージです(pngに変換しています)。

環境

$ cat /etc/oracle-release 
Oracle Linux Server release 6.6
$ uname -r
2.6.39-400.17.1.el6uek.x86_64
$ java -version
java version "1.8.0_102-ea"
Java(TM) SE Runtime Environment (build 1.8.0_102-ea-b04)
Java HotSpot(TM) 64-Bit Server VM (build 25.102-b04, mixed mode)
$ mvn -v
Apache Maven 3.3.9 (bb52d8502b132ec0a5a3f4c09453c07478323dc5; 2015-11-11T01:41:47+09:00)
Maven home: /opt/apache-maven-3.3.9

補足

Javaの謎のパフォーマンス劣化現象との戦い - Cybozu Inside Out | サイボウズエンジニアのブログ で紹介されているコードキャッシュが一杯になった後、JITコンパイラが停まる問題は jdk8、8u20 で修正されています。

The above mentioned issues have been fixed in JDK8 and its updates. Here's the list of the bugs that have been fixed in jdk8 and 8u20 that address these problems:

  • JDK-8006952: CodeCacheFlushing degenerates VM with excessive codecache freelist iteration (fixed in 8)
  • JDK-8012547: Code cache flushing can get stuck without completing reclamation of memory (fixed in 8)
  • JDK-8020151: PSR:PERF Large performance regressions when code cache is filled (fixed in 8)
  • JDK-8029091 Bug in calculation of code cache sweeping interval (fixed in 8u20)
  • 8027593: performance drop with constrained codecache starting with hs25 b111 (fixed in 8)
https://blogs.oracle.com/poonam/entry/why_do_i_get_message

jittest/readme.md at master · martint/jittest · GitHub と同じですが、以下検証結果です。

OpenJDK 1.7.0_79 では再現

Code cahce size が約 20MB で頭打ちになりJITコンパイラが停止後、Java バイトコードが毎度ネイティブコードに変換されるようになり秒間実行回数が約40回に落込んでいます。

  • グラフ

  • テストケース実行手順
$ java -version
java version "1.7.0_79"
OpenJDK Runtime Environment (rhel-2.5.5.3.0.1.el6_6-x86_64 u79-b14)
OpenJDK 64-Bit Server VM (build 24.79-b02, mixed mode)
$ java -XX:ReservedCodeCacheSize=20m -XX:InitialCodeCacheSize=20m -jar target/jittest-1.0-SNAPSHOT-standalone.jar > jittest_jvm-170_79.log
$ head -5 jittest_jvm-170_79.log 
Timestamp	Compilation Time	Code Cache Size	Perm Gen/Metaspace Size	Invocations/s
1462686065070	984	691840	5126184	35.98
1462686066074	1903	992512	5792376	70.64
1462686067074	3173	1366656	6292584	96.11
1462686068075	4187	1681856	6853904	121.67
$ tail -5 jittest_jvm-170_79.log 
1462686157127	60682	18579200	41666872	38.04
1462686158128	60682	18579200	41745208	38.00
1462686159128	60682	18579200	41834424	37.77
1462686160128	60682	18579200	41921464	38.14
1462686161129	60682	18579200	41999800	37.96
OpenJDK 1.8.0_102 では再現せず

JITコンパイルとコードキャッシュの解放が繰返され Code cache size は約 6〜14MB で推移し、秒間実行回数は約 140〜180 回で安定しています。OpenJDK 1.7.0 でJITコンパイラが停止した時のような実行回数の落込みは発生していません。

  • グラフ

  • テストケース実行手順
$ java -version
java version "1.8.0_102-ea"
Java(TM) SE Runtime Environment (build 1.8.0_102-ea-b04)
Java HotSpot(TM) 64-Bit Server VM (build 25.102-b04, mixed mode)
$ java -XX:ReservedCodeCacheSize=20m -XX:InitialCodeCacheSize=20m  -jar target/jittest-1.0-SNAPSHOT-standalone.jar > jittest_jvm-180_102.log &
$ java -version
java version "1.8.0_102-ea"
Java(TM) SE Runtime Environment (build 1.8.0_102-ea-b04)
Java HotSpot(TM) 64-Bit Server VM (build 25.102-b04, mixed mode)
$ head -5 jittest_jvm-180_102.log 
Timestamp	Compilation Time	Code Cache Size	Perm Gen/Metaspace Size	Invocations/s
1462686180191	990	2829824	4927976	24.55
1462686181197	2141	4131136	5538912	46.75
1462686182197	3251	5429952	5981560	68.45
1462686183198	4362	5321984	6334200	83.96
$ tail -5 jittest_jvm-180_102.log 
1462686539498	252194	10859520	9352688	175.20
1462686540498	252985	11689984	9745640	176.36
1462686541500	253685	12466368	10108464	175.21
1462686542500	254356	13176064	10445664	171.86
1462686543500	254793	13567616	10771176	167.98

蛇足

OpenJDK 7u60 の HotSpot VM のコードに https://github.com/brendangregg/Misc/blob/master/java/openjdk8_b132-fp.diff の変更を入れてビルドしかけたけど、続きはまた今度に。

# curl -L -O https://www.mercurial-scm.org/release/centos6/RPMS/x86_64/mercurial-3.7.3-1.x86_64.rpm
# rpm -ivh mercurial-3.7.3-1.x86_64.rpm 
$ export LANG=C
$ curl -L -O http://archive.apache.org/dist/ant/binaries/apache-ant-1.7.1-bin.tar.bz2
$ tar xfvj apache-ant-1.7.1-bin.tar.bz2
$ vi ~/.bash_profile
PATH=...:$HOME/Downloads/bin/apache-ant-1.7.1/bin
ANT_HOME=$HOME/Downloads/bin/apache-ant-1.7.1
export ... ANT_HOME
$ source ~/.bash_profile 
$ hg clone http://hg.openjdk.java.net/jdk7u/jdk7u60 jdk7u60
$ cd jdk7u60
$ sh ./get_source.sh
$ unset LD_LIBRARY_PATH
$ make sanity
$ make all

参考

関連

*1:テストケース(Java)を実行したと同じログインセッションで perf-map-agent を実行しないとSolved: Attaching the Java Agent to a Running JVM Process - Community | AppDynamics のエラーが出た