sbt testが途中で止まってしまうのを調査する - まーぽんって誰がつけたの？

状況

f:id:masato47744:20170422005236p:plain

という状態になってしまって困った。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領域が減らないのはなんでなのかはよく分かってないけども。