nekop's blog

OpenShift / JBoss / WildFly / Infinispanの中の人 http://twitter.com/nekop

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

perfはLinuxの性能解析ツールです。

$ 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の状況など幅広く拾ってくれてスナップショットにまとめてくれて解析超簡単。