JavaのCPUプロファイリング
JBoss / WildFly (全部俺) Advent Calendar 2013の19日目です。Java一般なトピック寄りで。
自分で主に利用するJavaのプロファイラはYourKitなのですが、YourKitを購入していない場合で性能問題を解析するときとかに何が使えるかなぁと思って調べてみました。
$ uname -a Linux localhost.localdomain 3.11.10-301.fc20.x86_64 #1 SMP Thu Dec 5 14:01:17 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux $ java -version java version "1.7.0_45" OpenJDK Runtime Environment (fedora-2.4.3.0.fc20-x86_64 u45-b15) OpenJDK 64-Bit Server VM (build 24.45-b08, mixed mode)
FedoraのOpenJDKを使う場合はdebuginfoを事前にインストールします。入っていないとlibjvm.soのシンボルが見えません。
$ sudo debuginfo-install java-1.7.0-openjdk
まずは普通に起動してみます。1.3秒です。
$ ./standalone.sh 15:54:07,063 INFO [org.jboss.as] (Controller Boot Thread) JBAS015874: JBoss EAP 6.2.0.GA (AS 7.3.0.Final-redhat-14) started in 1305ms - Started 129 of 186 services (56 services are passive or on-demand)
hprof
ふつうのJavaのhprofです。-agentlib:hprof=cpu=samplesをJava VMオプションに追加します。結果はjava.hprof.txtに出力されます。
$ vi ./standalone.conf $ ./standalone.sh 17:05:55,614 INFO [org.jboss.as] (Controller Boot Thread) JBAS015874: JBoss EAP 6.2.0.GA (AS 7.3.0.Final-redhat-14) started in 1580ms - Started 129 of 186 services (56 services are passive or on-demand) $ grep -A11 "^CPU SAMPLES BEGIN" java.hprof.txt CPU SAMPLES BEGIN (total = 1349) Tue Dec 17 17:07:31 2013 rank self accum count trace method 1 45.14% 45.14% 609 300838 sun.nio.ch.EPollArrayWrapper.epollWait 2 18.46% 63.60% 249 300299 java.lang.ClassLoader.defineClass1 3 7.64% 71.24% 103 301073 java.net.PlainSocketImpl.socketAccept 4 1.63% 72.87% 22 300300 java.util.zip.Inflater.inflateBytes 5 0.67% 73.54% 9 301142 java.io.FileDescriptor.sync 6 0.44% 73.98% 6 300071 java.lang.ClassLoader.findBootstrapClass 7 0.44% 74.43% 6 300358 java.util.zip.ZipFile.open 8 0.30% 74.72% 4 300722 java.util.zip.ZipFile.getNextEntry 9 0.30% 75.02% 4 300751 java.util.zip.ZipFile.getEntry 10 0.30% 75.32% 4 300954 sun.misc.Unsafe.unpark
多少のオーバヘッドがあり、起動時間が増加しています。hprofではJavaのメソッドレベルでのプロファイル結果となり、ネイティブ側の詳細は計測できません。
cpu=timesは遅すぎて使い物になりませんし、JBoss EAP 6を計測対象にした場合はcpu=timesのプロファイルではクラスロードの挙動が変わってしまい、クラスローディングに失敗してまともに起動しなくなると思います。
perf
$ sudo yum install perf -y $ perf record ./standalone.sh 15:56:35,771 INFO [org.jboss.as] (Controller Boot Thread) JBAS015874: JBoss EAP 6.2.0.GA (AS 7.3.0.Final-redhat-14) started in 1339ms - Started 129 of 186 services (56 services are passive or on-demand) $ perf report
perfではJavaのメソッドは見えません。ネイティブコードやJava VMのコードなどJavaメソッド以外の部分のパフォーマンスは見られます。
パフォーマンス劣化はほぼありません。
oprofile-jit
oprofileはLinuxの定番の性能解析ツールですが、oprofile-jitを使うとJITコンパイルされたJavaのメソッドもプロファイルできます。インタプリタ実行されているJavaメソッドはプロファイルできないので、起動処理やライフタイムの短いアプリケーションのプロファイルには向きません(Thanks to @YaSuenag)。Java VMオプションに-agentlib:jvmti_oprofileを指定して有効化します。データは実行ディレクトリのperf.dataに保存されます。
$ sudo yum install oprofile-jit -y $ vi ./standalone.conf $ operf ./standalone.sh 16:25:22,161 INFO [org.jboss.as] (Controller Boot Thread) JBAS015874: JBoss EAP 6.2.0.GA (AS 7.3.0.Final-redhat-14) started in 1750ms - Started 129 of 186 services (56 services are passive or on-demand) $ opreport -l | head Using /home/nekop/usr/local/jboss-eap-6.2.0/bin/oprofile_data/samples/ for samples directory. warning: /no-vmlinux could not be found. warning: [vdso] (tgid:25791 range:0x7fff2a5fe000-0x7fff2a5fffff) could not be found. CPU: Intel Sandy Bridge microarchitecture, speed 3.4e+06 MHz (estimated) Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (No unit mask) count 100000 samples % image name app name symbol name 15978 13.5321 25791.jo java Interpreter 9328 7.9001 no-vmlinux java /no-vmlinux 5271 4.4641 libjvm.so java SymbolTable::lookup_only(char const*, int, unsigned int&) 3310 2.8033 libz.so.1.2.8 java inflate_fast 1332 1.1281 libjvm.so java Symbol::equals(char const*, int) const 1224 1.0366 libz.so.1.2.8 java inflate 1136 0.9621 libjvm.so java ClassFileParser::parse_method(constantPoolHandle, bool, AccessFlags*, typeArrayHandle*, typeArrayHandle*, typeArrayHandle*, Thread*) $ opreport -l | head -n 50 | grep java.lang Using /home/nekop/usr/local/jboss-eap-6.2.0/bin/oprofile_data/samples/ for samples directory. warning: /no-vmlinux could not be found. warning: [vdso] (tgid:25791 range:0x7fff2a5fe000-0x7fff2a5fffff) could not be found. 434 0.3676 25791.jo java boolean java.lang.String.equals(java.lang.Object) 303 0.2566 25791.jo java int java.lang.String.hashCode()
ネイティブに加えてJITコンパイルされたJavaのメソッドも見えるのが良いですね。JITコンパイルされる前のインタプリタ実行はInterpreterというエントリとして見えます。
起動時間を見ると元に比べ130-140%くらいに増加しており、少しオーバヘッドがあります。operfコマンドに関係なくJava VMオプションに-agentlib:jvmti_oprofileが追加されているだけでもオーバヘッドが発生するので、プロファイル以外では削除しましょう。
NetBeans Profiler / VisualVM
これら2つはモノは一緒です。NetBeansからトラブルシューティング関連機能を抜き出したのがVisualVMです。
VisualVMでは起動時からアタッチすることができないので、起動からプロファイルしたい場合はデバッガを併用しなければなりません。NetBeans Profilerなら大丈夫でしょう。
そしてNetBeans Profilerを使ってみようと思ってNetBeans 7.4をダウンロードしたんですが起動しないのでポイしました。
$ ./netbeans Xlib: extension "XInputExtension" missing on display ":0".
Eclipse TPTP
めんどくさくなってきたのでもういいよね。
まとめ
YourKit買いましょう。YourKitであればパフォーマンス劣化の少ないサンプリング実行するだけでもコールスタックの閲覧、メモリの推移、スレッドの推移やCPUの状況など幅広く拾ってくれてスナップショットにまとめてくれて解析超簡単。
