sbt testが途中で止まってしまうのを調査する
状況
という状態になってしまって困った。sbtがグローバルで利用するsbtoptsもプロジェクト共通で指定してるやつがあって他の人は問題なさそうとのこと。ただ、OutOfMemoryなのでJVMのステータスみたいのが見たいと思って調べ始めた。
:dancers: JVMのパフォーマンスを見るにはjstat
jstat - Java 仮想マシン統計データ監視ツール
というのがある。
使い方はこんな感じ :point_down: jps
でプロセス番号を探して、jstat -gcutil <プロセス番号> <出力の間隔>
。
ざっくり、S0
とかS1
とかは各領域の使用率みたいなのを表してて、GC
ってついてるやつはガベージコレクションの回数を表してる。
$ jps 66803 sbt-launch.jar 67844 Jps $ jstat -gcutil 66803 200 S0 S1 E O M CCS YGC YGCT FGC FGCT GCT 0.00 6.25 4.31 18.41 84.36 91.64 43 0.051 0 0.000 0.051 0.00 6.25 6.00 18.41 84.36 91.64 43 0.051 0 0.000 0.051
:flashlight:sbtが途中で止まってるときはどんなことが起きていたか
JVMは、New領域(さらにEden、S0、S1と分かれる)とOld領域っていうのがあるが、Eden、Old領域が100%で張り付いていて、Full GCがずーっと続いている状態だった。最後OOMで終わったときにはFullGCが357回。
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT ・ 中略 ・ 0.00 100.00 100.00 100.00 97.14 95.17 144 15.169 273 1134.327 1149.496 0.00 99.99 100.00 100.00 97.14 95.17 144 15.169 274 1139.459 1154.628 0.00 99.99 100.00 100.00 97.14 95.17 144 15.169 274 1139.459 1154.628 0.00 99.99 100.00 100.00 97.14 95.17 144 15.169 274 1139.459 1154.628 0.00 99.99 100.00 100.00 97.14 95.17 144 15.169 274 1139.459 1154.628 0.00 99.99 100.00 100.00 97.14 95.17 144 15.169 274 1139.459 1154.628 0.00 100.00 100.00 100.00 97.14 95.17 144 15.169 275 1140.528 1155.697 0.00 100.00 100.00 100.00 97.14 95.17 144 15.169 275 1140.528 1155.697 0.00 100.00 100.00 100.00 97.14 95.17 144 15.169 275 1140.528 1155.697 0.00 100.00 100.00 100.00 97.14 95.17 144 15.169 275 1140.528 1155.697 0.00 100.00 100.00 100.00 97.14 95.17 144 15.169 275 1140.528 1155.697 0.00 100.00 100.00 100.00 97.14 95.17 144 15.169 275 1140.528 1155.697 0.00 100.00 100.00 100.00 97.14 95.17 144 15.169 275 1140.528 1155.697 ・ 中略 ・ 0.00 99.99 100.00 100.00 97.14 95.17 144 15.169 357 1529.127 1544.296 0.00 99.99 100.00 100.00 97.14 95.17 144 15.169 357 1529.127 1544.296 0.00 99.99 100.00 100.00 97.14 95.17 144 15.169 357 1529.127 1544.296 0.00 99.99 100.00 100.00 97.14 95.17 144 15.169 357 1529.127 1544.296 0.00 99.99 100.00 100.00 97.14 95.17 144 15.169 357 1529.127 1544.296 0.00 0.00 0.25 12.98 91.66 89.80 144 15.169 357 1530.162 1545.331 0.00 0.00 0.25 12.98 91.66 89.80 144 15.169 357 1530.162 1545.331 ↑ oomで終了
プロジェクトで推奨していたsbtoptsのNewSizeがよくなかった?
今まで特に問題なかったsbtoptsの設定
-J-Xmx4096m -J-Xms2048m -J-Xss1M -J-XX:MetaspaceSize=512m -J-XX:MaxMetaspaceSize=1024m -J-XX:+UseConcMarkSweepGC -J-XX:+CMSClassUnloadingEnabled -J-XX:NewSize=1024m -J-XX:MaxNewSize=3072m -J-XX:NewRatio=8 -J-Xss2M -Duser.timezone=GMT
Old領域が100%で詰まっているっていうことで-J-XX:NewSize=1024m
と-J-XX:MaxNewSize=3072m
が怪しい。そもそも、NewRatioを指定しているので、矛盾している?ような状態になっていた。
NewRatio=8ということは、New領域 : Old領域 = 1 : 8
ということらしい。
しかし、MaxNewSizeを3072mとしていたので、多分、つまり始めてしまったころには、New領域 : Old領域 = 3072 : (4096 - 3072) = 3 : 1
ぐらいに逆転状態になってしまってしまったのではと推測。
FullGCしてもOld領域が減らないのはなんでなのかはよく分かってないけども。
NewRatio=8だけでやってみた
FullGCも10回で、sbt testも最後までいくようになった。もうちょいパラメータチューニングしてみてもいいというか、ヒープサイズ自体をもっとでかくしてもいいかもとは思うけど、とりあえずいけるようになったからよかった。
まとめ
jstatというコマンドを生まれて初めて打ちました:tada: