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


# 概要
JavaのCPUプロファイラである[JIP(The Java Interactive Profiler)](http://jiprof.sourceforge.net/ "JIP")のメモです。
以下を示します。

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

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

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

# インストールと使い方
## ダウンロード
```bash: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の展開
```bash:JIPの展開
unzip jip-src-1.2.zip
```

### antの入手
ビルドにはantが必要です。

```bash: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をビルド
```bash: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プロセスの起動オプションに以下を指定
```bash: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に書かれています。
基本的にはデフォルトで良いと思いますが、以下だけ変更します。

```bash:プロファイルのプロパティで変更した方が良い点
#file=profile.txt
file=/path/to/output_dir
```

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

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

```bash:プロファイルの開始
cd /path/to/jip-src-1.2/client
chmod u+x start.sh
./start.sh localhost 15599
```

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

## プロファイル停止
```bash:プロファイルの停止
chmod u+x finish.sh
./finish.sh localhost 15599
```
finish.shは必要に応じてJAVA_HOMEを設定します。

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

```bash:ビューワの起動
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](http://fess.codelibs.org/ja/ "Fess")を対象にします。

## 動作確認環境
```bash: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
```
```bash:OSバージョン
$ cat /etc/redhat-release 
CentOS release 6.5 (Final)
```
```bash: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
```
```bash: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
```

## プロファイル取得
```bash:プロファイル開始
/path/to/jip-src-1.2/client/start.sh localhost 15599
```
```bash:以下にアクセス
http://localhost:8080/fess/search?query=hoge&sort=tstamp.asc&num=20
```
```bash:プロファイル停止
/path/to/jip-src-1.2/client/finish.sh localhost 15599
```

## ビューワで結果確認
```bash:ビューワの起動
java -jar /path/to/jip-src-1.2/tools/jipViewer.jar /path/to/output_dir/<timestamp>.xml
```
各タブの見方は以下の通りです。

* call treeタブ
 * スレッド別で実行メソッドの呼び出し階層を見ることができます。
メソッドを選択すると、メソッド自体の情報、呼び出し先メソッドの情報、呼び出し元メソッドの情報が下のビューに表示されます。
ダブルクリックでそのメソッドにジャンプできます。
![jip-viewer-calltree.png](https://qiita-image-store.s3.amazonaws.com/0/36003/0d4be853-00d4-44fc-be76-69dfd958a7da.png)
* methodタブ
 * メソッド一覧が表示されます。
カラム名をクリックするとソートできます。
countはそのメソッドが呼び出された回数、netはそのメソッド単体でかかった時間と割合、totalは呼び出し先も含めてかかった時間と割合です。
1スレッドで100%となるため、複数スレッドが何度も呼ぶようなメソッドの場合は割合は100%を超えることがあります。
下のペインはcall treeタブと同様で選択したメソッドの情報と呼び出し先/呼び出し元の情報です。
![jip-viewer-method.png](https://qiita-image-store.s3.amazonaws.com/0/36003/612df339-76d7-fe55-dfb4-cf0c3a59c718.png)
* by package
 * パッケージ別にかかった時間と割合を表示します。
![jip-viewer-package.png](https://qiita-image-store.s3.amazonaws.com/0/36003/41c288ba-76c5-db1d-8393-35174fcda62a.png)
* remote control
 * リモートのプロファイル対象にstart/stopができるようです。(動作未確認)
* help
 * ヘルプのようですが今回の環境では表示されませんでした。

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

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

## abのシナリオ
```bash: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への影響
以下のようなスクリプトを負荷を掛けていた間動かして取得した値の平均を取ります。

```bash: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](https://github.com/chewiebug/GCViewer "GCViewer")を使って見たところプロファイルON時はGC頻発、メモリ使用量も高止まりという状況でした。JIPありプロファイルOFFの状態でもJIP無しよりは若干高いようです。
![GC.jpg](https://qiita-image-store.s3.amazonaws.com/0/36003/8c187366-5956-8d30-5cce-b52bf10d25fb.jpeg)

# まとめとその他注意

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