Java5でも動くCPUプロファイラJIPの使い方

概要

JavaのCPUプロファイラであるJIP(The Java Interactive Profiler)のメモです。
以下を示します。

• インストール方法及び使い方
• Tomcat上のアプリをプロファイル対象とした例
• パフォーマンスへ与える影響

JIPの特徴

CPUプロファイラです。メソッド単位での処理時間や呼ばれた回数等を取得できます。
Java6以降であればvisualvmやMissionControl等ありますが、JIPはJava5でも動きます。
Java5でデフォルトで利用できるhprofよりも優れた点として以下が挙げられます。

• パフォーマンスへの影響が小さい
• 任意のタイミングでon/offできる
• フィルター設定(プロファイル対象のパッケージ/クラスを指定可能)等が可能

インストールと使い方

ダウンロード

JIPのダウンロード

wget "http://downloads.sourceforge.net/project/jiprof/jip/1.2/jip-src-1.2.zip?r=http%3A%2F%2Fsourceforge.net%2Fprojects%2Fjiprof%2F&use_mirror=jaist"

展開してビルド

ソースで配布されているため、ビルドが必要です。

JIPの展開

JIPの展開

unzip jip-src-1.2.zip

antの入手

ビルドにはantが必要です。

antのダウンロードと展開

wget http://ftp.jaist.ac.jp/pub/apache/ant/binaries/apache-ant-1.9.3-bin.tar.gz
tar xfz apache-ant-1.9.3-bin.tar.gz
rm apache-ant-1.9.3-bin.tar.gz
mv apache-ant-1.9.3 ant

antを使ってJIPをビルド

JIPのビルド

cd jip-src-1.2/
export JAVA_HOME=/path/to/jdk
export ANT_HOME=/path/to/ant
export PATH=$JAVA_HOME/bin:$ANT_HOME/bin:$PATH
ant dist

任意のJavaプロセスの起動オプションに以下を指定

Javaオプションに指定

-javaagent:/path/to/profile.jar -Dprofile.properties=/path/to/webapp.profile.properties

profiler.jarとwebapp.profile.propertiesはビルドが成功していればjip-src-1.2/profile/に置かれています。
プロパティファイルで指定可能な項目の詳細はjip-src-1.2/doc/profile-properties.htmlに書かれています。
基本的にはデフォルトで良いと思いますが、以下だけ変更します。

プロファイルのプロパティで変更した方が良い点

#file=profile.txt
file=/path/to/output_dir

上記を指定しておけば、プロファイルをon/offするたびに/path/to/output_dirにタイムスタンプ付きでファイルが出来上がります。指定しない場合はJavaプロセスを立ち上げたディレクトリにprofile.txtおよび、profile.xmlというファイルが出来上がり、毎回上書きされてしまいます。

プロファイル開始

デフォルトではJavaプロセス起動時にプロファイルは開始されません。
以下の手順で開始します。

プロファイルの開始

cd /path/to/jip-src-1.2/client
chmod u+x start.sh
./start.sh localhost 15599

start.shは必要に応じてJAVA_HOMEを設定します。

プロファイル停止

プロファイルの停止

chmod u+x finish.sh
./finish.sh localhost 15599

finish.shは必要に応じてJAVA_HOMEを設定します。

結果確認

/path/to/output_dirに.txtと.xmlファイルの2つができているはずです。
どちらもエディタ等で開いて読むこともできますが、以下を実行すると専用のビューワが開きます。

ビューワの起動

java -jar /path/to/jip-src-1.2/tools/jipViewer.jar /path/to/output_dir/<timestamp>.xml

実行にはGUI環境が必要です。
ビューワのヘルプファイルは/path/to/jip-src-1.2/src/com/tivo/jipviewer/help.htmlにありますが、あまり詳しく書かれていません。
見方はキャプチャ付きで後述します。

Tomcatを例とした使い方

今回はTomcat上のアプリとして全文検索システムのFessを対象にします。

動作確認環境

Kernelバージョン

$ uname -a
Linux hostname.example.com 2.6.32-431.el6.x86_64 #1 SMP Fri Nov 22 03:15:09 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

OSバージョン

$ cat /etc/redhat-release 
CentOS release 6.5 (Final)

Tomcat/Fessバージョン

$ /opt/fess-server-8.2.0/bin/version.sh
Using CATALINA_BASE:   /opt/fess-server-8.2.0
Using CATALINA_HOME:   /opt/fess-server-8.2.0
Using CATALINA_TMPDIR: /opt/fess-server-8.2.0/temp
Using JRE_HOME:        /usr/java/jdk1.7.0_10
Using CLASSPATH:       /opt/fess-server-8.2.0/bin/bootstrap.jar:/opt/fess-server-8.2.0/bin/tomcat-juli.jar
Server version: Apache Tomcat/7.0.42
Server built:   Jul 2 2013 08:57:41
Server number:  7.0.42.0
OS Name:        Linux
OS Version:     2.6.32-431.el6.x86_64
Architecture:   amd64
JVM Version:    1.7.0_10-b18
JVM Vendor:     Oracle Corporation

Javaオプション(デフォルト＋GCログ出力＋JIP設定です)

$ . /opt/fess-server-8.2.0/bin/setenv.sh ; echo $JAVA_OPTS
-Dsolr.solr.home=/solr -Dfess.solr.data.dir=/solr/core1/data -Dfess.log.file=/webapps/fess/WEB-INF/logs/fess.out -Djava.awt.headless=true -server -Xmx1g -XX:MaxPermSize=128m -XX:-UseGCOverheadLimit -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=75 -XX:+CMSIncrementalMode -XX:+CMSIncrementalPacing -XX:CMSIncrementalDutyCycleMin=0 -XX:+UseParNewGC -XX:+UseStringCache -XX:+UseTLAB -XX:+DisableExplicitGC -XX:+UseCompressedOops -XX:+UseCompressedStrings -XX:+OptimizeStringConcat -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:/opt/fess-server-8.2.0/logs/gc/gc-20140207162842.log -javaagent:/opt/jip-src-1.2/profile/profile.jar -Dprofile.properties=/opt/jip-src-1.2/profile/webapp.profile.properties

プロファイル取得

プロファイル開始

/path/to/jip-src-1.2/client/start.sh localhost 15599

以下にアクセス

http://localhost:8080/fess/search?query=hoge&sort=tstamp.asc&num=20

プロファイル停止

/path/to/jip-src-1.2/client/finish.sh localhost 15599

ビューワで結果確認

ビューワの起動

java -jar /path/to/jip-src-1.2/tools/jipViewer.jar /path/to/output_dir/<timestamp>.xml

各タブの見方は以下の通りです。

• call treeタブ
  • スレッド別で実行メソッドの呼び出し階層を見ることができます。 メソッドを選択すると、メソッド自体の情報、呼び出し先メソッドの情報、呼び出し元メソッドの情報が下のビューに表示されます。 ダブルクリックでそのメソッドにジャンプできます。
• methodタブ
  • メソッド一覧が表示されます。 カラム名をクリックするとソートできます。 countはそのメソッドが呼び出された回数、netはそのメソッド単体でかかった時間と割合、totalは呼び出し先も含めてかかった時間と割合です。 1スレッドで100%となるため、複数スレッドが何度も呼ぶようなメソッドの場合は割合は100%を超えることがあります。 下のペインはcall treeタブと同様で選択したメソッドの情報と呼び出し先/呼び出し元の情報です。
• by package
  • パッケージ別にかかった時間と割合を表示します。
• remote control
  • リモートのプロファイル対象にstart/stopができるようです。(動作未確認)
• help
  • ヘルプのようですが今回の環境では表示されませんでした。

パフォーマンス影響

以下の状態でabで負荷をかけて結果(abの結果とCPU使用率、ヒープ使用率)を確認しました。
負荷を掛ける対象は上記と同じTomcat(上のFess)です。

1. JIPを入れてない状態
2. JIPを入れてプロファイルがONの状態
3. JIPを入れてプロファイルがOFFの状態

abのシナリオ

abのシナリオ

ab -n 100 -c 5 "http://localhost:8080/fess/search?query=hoge&sort=tstamp.asc&num=20"

並列度も回数も少ないのは高負荷にするとプロファイルONの際にタイムアウトでエラーになってしまったためです。
JMeter等を使ってちゃんとしたシナリオを組んで長時間の負荷を確認できれば良かったんですが、時間の都合で未実施です。

abの結果

Requests per secondとTime per requestの値は以下のとおりです。

	JIP無し	JIPありプロファイルOFF	JIPありプロファイルON
Requests per second	79.46	7.20	1.33
Time per request(msec)	12.58	138.91	749.28

大分影響が大きいことが分かります。JIP有りだとプロファイルをONにしていなくてもそれなりのオーバーヘッドがあることが分かります。

CPUへの影響

以下のようなスクリプトを負荷を掛けていた間動かして取得した値の平均を取ります。

CPU取得

while true
do
  ps --noheader -o pcpu $(pgrep -f fes[s])
  sleep 1
done

結果はこんな感じです。

JIP無し	JIPありプロファイルOFF	JIPありプロファイルON
11.4	16.2	35.0

メモリ

出力したGCログをGCViewerを使って見たところプロファイルON時はGC頻発、メモリ使用量も高止まりという状況でした。JIPありプロファイルOFFの状態でもJIP無しよりは若干高いようです。

まとめとその他注意

• JIPのインストール方法と使い方をまとめました。
• パフォーマンスへの影響が少ないとありましたが、今回確認した範囲では十分大きいことが分かりました。
  • JIP設定してOFFのままでもそれなりにオーバーヘッドがあったので、本番環境等でJIP設定してOFFにしておいて何かあったらONにするみたいな使い方ができなそうです。
  • 今回は載せてませんが、Javaのバージョン等にも依存するかと思い、Java5の業務アプリでもプロファイルしてみましたが、十分に影響がありました。
  • 今回は載せていませんが、呼び出しクラスが増えるほどプロファイルに時間がかかるようです。
  • 今回は載せていませんが、scala等別のJVM言語で書かれたプロセスだと特に時間がかかるようです。
• 最近のJavaのバージョンで動かす場合はvisualvm等の方が良いかと思います。
• プロファイルを仕掛けているとJavaプロセスが正常停止しない(今回はTomcatなのでもともと止まらないこともあったりしますが)ことがありました。
• プロファイル結果のファイル出力は停止時にまとめて書き込むため、ONにしていた時間が長いとそれなりのIOが発生します。