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には大事なんだろうな、と最近品質強化を担当することになった男からの言葉を持って〆させてください。
最後まで読んでいただきありがとうございました！