Javaの謎のパフォーマンス劣化現象との戦い - Cybozu Inside Out

こんにちは。アプリケーション基盤チームの横田です。 Javaの謎のパフォーマンス劣化にまつわる調査をしていたのですが、1ヶ月の苦労の末に原因がわかりましたので、報告させていただきます！

公開後に頂いたはてなブックマークでのご指摘・社内でのタイポ・読みにくいなどの指摘を受けてたので、謹んで修正させいただきます。修正した内容につきましては、記事の最後を参照してください。

忙しい人のためのまとめ

jdk-7u4以降のjdk-7 *1 でJavaのパフォーマンスが劣化する謎の現象
CodeCacheの容量限界に近づくとJITコンパイラを停止してコンパイルしたコードを捨てる機能が原因だった
起動オプションで回避できるので、長期運用するときは -XX:-UseCodeCacheFlushing, -XX:ReservedCodeCacheSize=128m をつける
上のオプションを設定した時に、CodeCacheの量が適切でない場合はログが出力されるので ReservedCodeCacheSize を適宜修正する

謎のパフォーマンス劣化

弊社でおきていた謎のパフォーマンス劣化の特徴は次のようなものでした

Javaの起動直後は高速に動作する
起動から数日経つとパフォーマンス劣化が顕著に発生する
IOボトルネックではない
パフォーマンス劣化が起き始めるとCPU利用率が2倍程度に増加する
CPU利用率は高まるが弊社環境ではCPUリソースには余裕があった
再起動すると現象は回復する

GC、メモリリーク、メモリの断片化によるパフォーマンス劣化などを疑ってみたのですが、どれも決定的な証拠に乏しく「原因はこれだ」と判断できずでした。

次のリンクは、JITコンパイラがCodeCacheの量が足りなくなった時に、プログラムのスループットが悪化する話。

GitHub - martint/jittest: Demonstrate JIT compiler issue in java 7

結果的にはこれが原因でした。

パフォーマンス悪化の原因はjdk7u4以降で導入されたCodeCacheFlusingという機能。以下、引用します

Why do I get message "CodeCache is full. Compiler has been disabled"? (Poonam Bajaj)

UseCodeCacheFlushing is set to false by default in JDK6, and is enabled by default since JDK7u4. This essentially means that in jdk6 when the CodeCache becomes full, it is not swept and flushed and further compilations are disabled, and in jdk7u+, an emergency flushing is invoked when the CodeCache becomes full. Enabling this option by default made some issues related to the CodeCache flushing visible in jdk7u4+ releases. The following are two known problems in jdk7u4+ with respect to the CodeCache flushing:

The compiler may not get restarted even after the CodeCache occupancy drops down to almost half after the emergency flushing.

The emergency flushing may cause high CPU usage by the compiler threads leading to overall performance degradation.

怪しい！　怪しすぎるよ！　この機能！

次のような挙動をします

ReservedCodeCacheSize が　CodeCacheMinimumFreeSpace 以下になるとJITコンパイラを停止
不要と判断されたコンパイル済みコードを捨てる。
CodeCacheFlushingMinimumFreeSpace 以下に CodeCacheが減るとJITコンパイラは活動を再開

弊社で開発しているJavaプログラムは起動直後にCodeCacheが30MB程度に到達します。そのため一度CodeCacheFlushingが発動してしまうと、JITコンパイラは復活してくれません。

実験

その1 jstatでJITコンパイラの動きを確かめてみる

jstat -compiler JavaはJITコンパイラの動きを観察することができます。

運用環境で稼働中のJavaプロセスに対して実行してみます。JITコンパイラが動いていないことが確認できました。

$ jstat -compiler ${JAVA_PID}
Compiled Failed Invalid   Time   FailedType FailedMethod
   14828      0       0   238.48          0             
   14828      0       0   238.48          0 
   ...           
   14828      0       0   238.48          0

全部コンパイルされてるんとちゃうんか？

書籍「Javaパフォーマンス」によると、JITコンパイラが停止するとログ出力すると書いてあります。しかし、ログ出力されていません。

ログ出力されない原因は、次の実験で判明するので、次の実験に進みます。次は、CodeCacheSizeが適切なのか検証します。

その2 UseCodeCacheFlushingをOffにする

jdk7u4以降のデフォルトの設定の場合、次のようなことがわかりました。

CodeCacheFlushingが動作するとJITコンパイラは停止する。
呼び出し頻度の少ないコード、脱最適化されたコードを削除する。
JITコンパイラが停止しても、ログを出力してくれない。
JITコンパイルが停止状態で、未コンパイルのコードはインタプリタ実行になるので性能劣化が発生する

ReservedCodeCacheSize, CodeCacheFlushingMinimumFreeSpace, CodeCacheMinimumFreeSpace などのオプションを変更して前述のJITコンパイラの動作確認用のレポジトリで実験するとよいです

GitHub - martint/jittest: Demonstrate JIT compiler issue in java 7

Java 7でCodeCacheが足りない時にログを出すためには、-XX:-UseCodeCacheFlushing を設定するしかありません。社内でこのオプションを設定して2日ほど経過して、CodeCacheが満杯になってJITコンパイラが停止していることがわかりました。

ログは、次のようになります

OpenJDK 64-Bit Server VM warning: CodeCache is full. Compiler has been disabled.
OpenJDK 64-Bit Server VM warning: Try increasing the code cache size using -XX:ReservedCodeCacheSize=
Code Cache  [0x00007fc715000000, 0x00007fc717fa0000, 0x00007fc718000000)

解決策

長期運用されるJavaプロセスには次のオプションを設定して問題が解決できました。

-XX:-UseCodeCacheFlushing でCodeCacheが足りなくなったら、JITコンパイラを止めるようにする。こうするとJITコンパイラ停止時にログが出力されます
-XX:ReservedCodeCacheSize=128m でCodeCacheSizeを2倍程度に増やす

リクエスト処理にかかる平均時間が少なくなりました f:id:cybozuinsideout:20160411101010p:plain

CPU利用率も1/2にほどに減少したことが確認できました f:id:cybozuinsideout:20160411101004p:plain

プログラムも高速化されるし、CPUにも優しい素晴らしいオプションですね！

Tips

CodeCacheの現在容量を確認する

現在利用中のCodeCacheSizeは jstat などで、監視することはできません。 JMXを活用したプロダクトを使うとCodeCacheの現在容量を見ることができます。次のようなプロダクトです。

Java 8はどうなるの？

Java 8の場合はデフォルトで次のオプション設定になるようです

ReservedCodeCacheSize は約250MB
UseCodeCacheFlushing デフォルト設定がtrue

Java 8の時には再度、起動オプションの検討をおねがいします！

おわりに

最後に調査の参考にさせていただいたサイト＆書籍です。

色々苦労しましたがJVMの中を読んだり、結構いい経験になりました。調査は社内の特別環境で、調査・検証を行いました。お客様の環境では、定期的に再起動して現象の影響が出ないようにしています。

修正履歴

2016/04/14

Java8でもUseCodeCacheFlushingがデフォルトでも有効であることを追記
CodeCacheFlushingMinimumFreeSpace と CodeCacheMinimumFreeSpace と CodeCacheFlushing の挙動が間違っていたので修正
タイポ・わかりにくい表現を修正

2016/04/27

jdk7u4が一部jdk7u40になっていたのでjdk7u4に統一

*1:Java 7のパブリック・アップデートは終了していますが、運用環境ではUbuntuがセキュリティパッチを適用したJava 7を利用しています