SRE Advent Calendar 2019 4日目（といっても結構日跨ぎしちゃいましたが、、）

こんにちは。
最近プロダクトの品質強化に取り組んでおります @dododo8m と申します。
今回は開発中に陥ってしまったJVMに関するトラブルとSREに関する気付きについてお話させてください。それでは張り切ってまいります。

さいしょに

弊社のプロダクトではデータパイプラインの基盤をk8s（EKS）で構築しております。
データ転送は k8sのjob で行っており、データ転送の処理は Embulk を使用しております。
以下、データ転送で生成されるPodのことを worker と呼びます。

ちなみに、以下の話では「workerのメモリサイズ上げれば良かったんじゃないの？」というツッコミが来そうなところがありますが、諸事情によりそうもいかずギリギリを攻めた戦いをしていたことをご了承ください。

JVMがクラッシュし始めた

開発のさなか、JVMのクラッシュが頻発するようになりました。

#
# A fatal error has been detected by the Java Runtime Environment:
#
#  SIGSEGV (0xb) at pc=0x00007ffa1389dc1e, pid=22, tid=0x00007ff9f5efe700
#
# JRE version: OpenJDK Runtime Environment (8.0_212-b04) (build 1.8.0_212-b04)
# Java VM: OpenJDK 64-Bit Server VM (25.212-b04 mixed mode linux-amd64 compressed oops)

エラーログを読み進めていくと、JVMはクラッシュした詳細は以下のログを読めとのことだったので

#
# An error report file with more information is saved as:
# /work/hs_err_pid22.log
#
# Compiler replay data is saved as:
# /work/replay_pid22.log
#

今度は、その指定されたログの中身を見に行くことにしました。
すると今度はこんな感じのエラーが


---------------  T H R E A D  ---------------

Current thread (0x00007fa4a815c800):  JavaThread "C2 CompilerThread0" daemon [_thread_in_native, id=34, stack(0x00007fa491cfe000,0x00007fa491dfe000)]

siginfo: si_signo: 11 (SIGSEGV), si_code: 1 (SEGV_MAPERR), si_addr: 0x0000000000000011

Registers:

なんじゃなんじゃと調べていったところ、コンパイラ・スレッドでクラッシュが発生したとのことでした。選べる回避策は以下の２つ。

強引な方法: HotSpot Client VMを指定するため、アプリケーションが-clientオプションで実行されるように構成を変更します。
丁寧な方法: java.lang.Thread.setPriorityメソッドのコンパイル中にのみバグが発生するものと想定して、このメソッドをコンパイルから除外します。

ここに書かれている内容を参考にしたとき、workerはデータ転送完了後に削除されるJobであるためclientモードにしても問題ないな、という判断が下されて 1. の強引な方法を採用しました。
これで、この問題自体は発生しないようになりました。めでたし。

ふたたびのJVMのクラッシュ

開発を進めていると再びJVMのクラッシュに遭遇しました。
所定のログを見に行ったところ以下のようなログがちらほら。またnew relicを入れていたのでメモリの状況など確認したところJVMに割り与えたメモリサイズなど通り越してPod自体がメモリ使用率100%になっていました。

Thread 0x00007faabc00a800 Exception <a 'java/lang/ArrayIndexOutOfBoundsException'> (0x00000000f9901dc8) thrown at [/home/openjdk/jdk8u/hotspot/src/share/vm/runtime/sharedRuntime.cpp, line 605]

なんだ？甘えるなよメモリ割り当てはそう簡単にはできんぞ（白目）
とりいそぎ jstatのgcutilオプションでJVMのメモリの動きなどを確認してみたとろ

/work# jstat  -gcutil 23 5000
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
  0.00  79.20  77.96  99.43  94.72  90.10    533   12.983    17    4.216   17.198
  0.00  99.21  38.33  99.43  94.72  90.10    535   13.028    17    4.216   17.243
 80.60   0.00  92.59  99.44  94.72  90.10    536   13.048    17    4.216   17.264
 93.99   0.00  48.78  99.44  94.72  90.10    538   13.091    17    4.216   17.307
 88.91   0.00   9.21  99.44  94.72  90.10    540   13.138    17    4.216   17.354
  0.00  99.95  63.51  99.45  94.72  90.10    541   13.160    17    4.216   17.375
  0.00   0.00  19.19  99.99  94.72  90.10    543   13.264    18    4.466   17.730
  0.00   0.00  98.17  99.06  94.72  90.10    543   13.264    19    4.695   17.959
  0.00   0.00  80.81  99.35  94.72  90.10    545   13.455    21    5.171   18.626
  0.00   0.00  65.73  99.01  94.72  90.10    547   13.705    23    5.693   19.398
  0.00   0.00  49.08  99.29  94.72  90.10    549   13.905    25    6.169   20.074

FGCが発生してもOld領域が全然へらぬ。これはメモリリークでも起こっているのかもしれない。
こうなったらがっつりFGCさせてやろう！ということで今度はGCの種類を変更してみることにしました。

現在使用しているGCを確認してみたところCMS(Concurrent Mark Sweep)を使用していました。ただ、workerさんはバッチ処理なのでFGCするならガッツリきれいにしてほしい、ということでパラレル型(スループット型)に変更してやりました。
すると・・・

/work# jstat -gcutil 22 5000
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
  0.00  31.25  11.06  19.26  94.45  91.28   1509    5.647     3    0.559    6.206
  0.00  37.50  97.44  19.28  94.45  91.28   1524    5.694     3    0.559    6.253
 37.50   0.00  38.36  19.29  94.45  91.28   1538    5.753     3    0.559    6.312
 37.50   0.00  85.55  19.31  94.45  91.28   1552    5.800     3    0.559    6.359
  0.00  37.50  30.43  19.33  94.45  91.28   1567    5.851     3    0.559    6.410
 43.75   0.00  72.44  19.35  94.45  91.28   1582    5.901     3    0.559    6.460
 31.25   0.00  51.40  19.37  94.45  91.28   1598    5.964     3    0.559    6.523
  0.00  37.50  64.40  19.38  94.45  91.28   1613    6.020     3    0.559    6.579
  0.00  37.50  80.54  19.40  94.45  91.28   1627    6.070     3    0.559    6.629

Old領域が全然へらぬ問題も解消され、無事JVMクラッシュすることもなくなりました。

学びや教訓

上記の出来事を受けて我々のプロジェクトではjstatのメトリクスをPrometheusで収集してnew relicで可視化・監視するようにしています。（詳細は別のアドベントカレンダーで記事化する予定です。）
パッツパツ状態であることには変わりないので、引き続き重要なメトリクスとして監視し続けたいと考えています。

今回の件で学びになったのは、ログやメトリクス収集の大切さとリソースチューニングの大変さでした。
正直JVMのこういった調査にも慣れていないところはあったのですが適切に情報を吐かせることで対応していくことができました。

また、今回のブログではさらっとは書いてはいますが正直すごく泥臭い作業でした。
でもこういう泥臭い作業に屈せず、正しい事実を積み上げて対応していくことがSREには大事なんだろうな、と最近品質強化を担当することになった男からの言葉を持って〆させてください。

最後まで読んでいただきありがとうございました！