JVM統計データの監視

プロセスIDを確認

JVMの統計データを監視するための準備として、ターゲットのプロセスIDを確認する。
tomcatで動かしているので、tomcatJVMプロセスIDを jps コマンドで確認する。

環境
デーモン起動した場合


[root@localhost ~]# service tomcat start
[root@localhost bin]# ps -ef | grep java
root 3011 1 0 09:17 ? 00:00:00 jsvc.exec -user root -home /usr/java/jdk -Dcatalina.home=/usr/local/tomcat -Dcatalina.base=/usr/local/tomcat -Djava.io.tmpdir=/var/tmp -wait 10 -pidfile /var/run/jsvc.pid -outfile /usr/local/tomcat/logs/catalina.out -errfile &1 -cp /usr/java/jdk/lib/tools.jar:/usr/local/tomcat/bin/commons-daemon.jar:/usr/local/tomcat/bin/bootstrap.jar -Xms128m -Xmx256m org.apache.catalina.startup.Bootstrap
root 3012 3011 5 09:17 ? 00:00:02 jsvc.exec -user root -home /usr/java/jdk -Dcatalina.home=/usr/local/tomcat -Dcatalina.base=/usr/local/tomcat -Djava.io.tmpdir=/var/tmp -wait 10 -pidfile /var/run/jsvc.pid -outfile /usr/local/tomcat/logs/catalina.out -errfile &1 -cp /usr/java/jdk/lib/tools.jar:/usr/local/tomcat/bin/commons-daemon.jar:/usr/local/tomcat/bin/bootstrap.jar -Xms128m -Xmx256m org.apache.catalina.startup.Bootstrap
root 3044 2866 0 09:17 pts/0 00:00:00 grep java

jpsコマンドで確認。3012のクラス名は空白。


[root@localhost bin]# jps
3035 Jps
3012

-vスイッチをつけて、JVM に渡される引数を出力


[root@localhost bin]# jps -v
3027 Jps -Dapplication.home=/usr/java/jdk1.5.0_15 -Xms8m
3012 -Dcatalina.home=/usr/local/tomcat -Dcatalina.base=/usr/local/tomcat -Djava.io.tmpdir=/var/tmp -Xms128m -Xmx256m abort

startup.shで起動した場合


[root@localhost bin]# ./startup.sh
[root@localhost bin]# ps -ef | grep java
root 2948 1 29 09:08 pts/0 00:00:02 /usr/java/jdk/bin/java -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djava.util.logging.config.file=/usr/local/tomcat/conf/logging.properties -Djava.endorsed.dirs=/usr/local/tomcat/endorsed -classpath :/usr/local/tomcat/bin/bootstrap.jar -Dcatalina.base=/usr/local/tomcat -Dcatalina.home=/usr/local/tomcat -Djava.io.tmpdir=/usr/local/tomcat/temp org.apache.catalina.startup.Bootstrap start
root 2964 2866 0 09:08 pts/0 00:00:00 grep java

jpsコマンドで確認。2948のクラス名としてBootstrapと表示される。


[root@localhost bin]# jps
2948 Bootstrap
2965 Jps

-vスイッチをつけて、JVM に渡される引数を出力


[root@localhost bin]# jps -v
2973 Jps -Dapplication.home=/usr/java/jdk1.5.0_15 -Xms8m
2948 Bootstrap -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djava.util.logging.config.file=/usr/local/tomcat/conf/logging.properties -Djava.endorsed.dirs=/usr/local/tomcat/endorsed -Dcatalina.base=/usr/local/tomcat -Dcatalina.home=/usr/local/tomcat -Djava.io.tmpdir=/usr/local/tomcat/temp

計測

構文や結果の見方はhttp://java.sun.com/j2se/1.5.0/ja/docs/ja/tooldocs/share/jstat.html#gcutil_option参照。

プロセス3012のガベージコレクション統計データを2秒おきに取得


jstat -gcutil 3012 2000

⇒結果


S0 S1 E O P YGC YGCT FGC FGCT GCT
0.00 44.36 59.37 2.13 79.59 11 0.050 1 0.000 0.050
0.00 44.36 59.37 2.13 79.59 11 0.050 1 0.000 0.050
0.00 44.36 59.37 2.13 79.59 11 0.050 1 0.000 0.050
0.00 44.36 59.37 2.13 79.59 11 0.050 1 0.000 0.050
0.00 44.36 59.37 2.13 79.59 11 0.050 1 0.000 0.050
0.00 44.36 61.17 2.13 79.59 11 0.050 1 0.000 0.050
0.00 44.36 61.17 2.13 79.59 11 0.050 1 0.000 0.050

  • Survivor領域は、今は1を使っており、44.36%使用
  • Eden領域は59.37%使用
  • Permanentは、79.59%使用 ※Permanent領域は、JVMにロードされたクラスの置き場所
  • Young領域のGCは11回行われ、トータル0.050(ミリ秒?)かかった
  • フル(Young+Old)GCは1回行われ、0.000(ミリ秒?)かかった  ・・・表示できないくらい短時間?
  • Young、フルGCの合計時間は0.050(ミリ秒?)であった

※Young = Survivor0 + Survivor1 + Eden

なんちゃってチューニング

手持ちのWebアプリを実行して計測、なんちゃってチューニングしてみた記録。
手持ちのWebアプリがメモリ無駄遣いしているという議論は、また別の機会に。
Permanentも危ないか・・・・

-Xms128m -Xmx256m

最初の設定。ヒープに128m〜256割り当てる。
一連の流れをテスト後


S0 S1 E O P YGC YGCT FGC FGCT GCT
0.00 65.27 52.55 64.83 99.81 217 3.610 6 1.000 4.610
検索とかすると、YoungGCが5秒で数十回行われてしまう。フルGCも6回。

-Xms256m -Xmx512

ヒープ割り当てメモリの最小も最大も倍にした。
一連の流れをテスト後


S0 S1 E O P YGC YGCT FGC FGCT GCT
100.00 0.00 48.54 39.23 99.05 66 2.230 3 0.330 2.560
検索する度に、YoungGCが3回程度実施される。フルGCは3回。

-Xms512m -Xmx512m

不足気味なので、最小を絞る必要もない。最小と最大を同じにした。
一連の流れをテスト後


S0 S1 E O P YGC YGCT FGC FGCT GCT
0.00 100.00 50.25 15.92 98.87 31 1.890 3 0.420 2.310
検索する度に、YoungGCが1〜3回程度実施される。フルGCは3回。

-Xms512m -Xmx512m -Xmn256m

new(Young)に最大の半分を割り当てた。(ヒープ全体の1/3〜1/2が適当とか)
一連の流れをテスト後


S0 S1 E O P YGC YGCT FGC FGCT GCT
84.60 0.00 14.37 12.44 98.94 4 1.260 2 0.370 1.630
検索する度に、YoungGCが1〜3回程度実施される。フルGCは2回。