JDKトラブルシューティング方法と事例紹介
NTT コムウェア株式会社

坂本 翔平 / 坂本 統

2022年09月03日

Copyright © NTT COMWARE CORPORATION 2022

技術企画部
技術SE部門 オープンソーステクノロジセンタ

目次◼ はじめに◼ 自己紹介◼ 本セッションについて◼ JDK のトラブルシューティングの基本◼ トラブル事例紹介◼ 事例１:長期安定化試験において Full GC 多発◼ 事例２:Java プロセスのクラッシュ◼ 事例３:Compressed Class Space 起因の OOME 発生◼ まとめ

Copyright © NTT COMWARE CORPORATION 2022

1

はじめに
◼ 自己紹介◼ 坂本

翔平◼ NTTコムウェア株式会社（2017年入社）◼ 技術企画部技術SE部門オープンソーステクノロジセンタ所属◼ Java & OpenJDK 関連技術チーム（2020年~）

◼ 坂本

統

◼ NTTコムウェア株式会社（2014年入社）◼ 技術企画部技術SE部門オープンソーステクノロジセンタ所属◼ Java & OpenJDK 関連技術チーム（2018年~）◼ OpenJDK Author

Copyright © NTT COMWARE CORPORATION 2022

2

はじめに
◼ 担当業務◼ 主に Java システム（OpenJDK など）のトラブルシューティングを実施◼ 特定の Java システムの専属ではなく、社内の Java システムの技術サポートを一括して請け負う◼ 年間 50~60 件程度対応◼ GC チューニング◼ OutOfMemoryError（OOME） 解析◼ JDK Flight Recorder（JFR） 解析◼ OpenJDK クラッシュ解析◼ OpenJDK 仕様調査（ソースコード解析）◼ etc.

◼ アプリケーション（AP）実装に関する解析（ユーザコードやミドルウェア、
フレームワークなど）は担当していない（別チームが実施）

Copyright © NTT COMWARE CORPORATION 2022

3

はじめに
◼ 本セッションについて◼ 社内の Java システムのトラブルシューティングを対応してきて得られた知見について紹介◼ 解析にはどのような情報を見る必要があるのか◼ GC の頻発による AP の性能が劣化したときは？
◼ OutOfMemoryError が発生したときは？
◼ Java プロセスがクラッシュしたときは？
◼ etc.

◼ 実際に経験したトラブルシューティング事例について◼ 本セッションでは３つ紹介◼ オーソドックスなものではなく、少し変わった観点が必要だったものをピックアップ◼ 本セッションの内容は JDK のトラブルシューティングに関わる話が中心◼ Java AP 開発者で Java Virtual Machine（JVM）の基礎知識（Java ヒープやGC の概念）は有しているがトラブルシューティングは初心者～中級者の方向け◼ Java 言語などのプログラミングや AP プロファイリングの話は本日の内容に含まれない点に注意
Copyright © NTT COMWARE CORPORATION 2022

4

JDK のトラブルシューティングの基本

Copyright © NTT COMWARE CORPORATION 2022

JDK のトラブルシューティングの基本◼ Java システムでは JDK に関連した様々な問題が発生するケースが多々ある◼ GC の頻発による AP の性能劣化◼ OutOfMemoryError の発生◼ Java プロセスの CPU 使用率の上昇◼ etc.

◼ JVM が出力する情報がどういった問題の解析に役立つか次ページ以降で個々に説明◼ 見るべき情報としては主に以下の通り ※Hotspot VM の場合のみ◼ GC ログ◼ ヒープダンプ◼ スレッドダンプ◼ JDK Flight Recorder◼ コアダンプ◼ その他

Copyright © NTT COMWARE CORPORATION 2022

6

JDK のトラブルシューティングの基本◼ GC ログ◼ GC（ガベージコレクション）の情報を出力したログ◼

Java ヒープの推移◼

GC 発生状況

GCViewer の画面◼ どういった問題の際に確認するか◼

GC の頻発による性能劣化◼

Java ヒープに関するエラーが発生◼ 確認のポイント◼

GC 発生前後の Java ヒープの使用量◼

Java ヒープの増加傾向◼ おススメ解析ツール◼

GCViewer◼

https://github.com/chewiebug/GCViewer

Minor GC の GC ログ出力例
2022-07-07T10:04:32.718+0900: 0.120: [GC (Allocation Failure) 2022-07-07T10:04:32.718+0900: 0.120:[ParNew: 200450K->331K(307840K), 0.0410143 secs] 200450K->96590K(991872K), 0.0410738 secs][Times: user=0.38 sys=0.03, real=0.04 secs]

処理に要した時間

New 領域の推移

ヒープ全体の推移
Copyright © NTT COMWARE CORPORATION 2022

7

JDK のトラブルシューティングの基本◼ GC ログ◼ 情報取得方法
以下の JVM 起動オプションを設定することで GC の情報が詳細出力される◼

Java 8 では以下を付与するのがおススメ◼

オプション名説明-XX:+PrintGCDetails

GC の情報を詳細出力する。

-XX:+PrintGCDateStamps

GC ログに日付と時刻を出力する。

-Xloggc:<filepath>

GC の情報を指定したファイルに出力する。

Java 9 以降は -Xlog:<option>（Unified Logging）※ で指定◼
◼

（設定例）-Xlog:gc=info,gc+heap=trace,vmoperation=debug:file=<filepath>:t,l,tg-Xlog のオプション

説明

gc=info

gc に関わる情報を出力する。

gc+heap=trace

gc とヒープに関わる情報を出力する。

vmoperation=debug

JVM 動作状況に関わる情報を出力する。

file

GC の情報を指定したファイルに出力する。

t,l,tg

ローカル時刻(t)、ログレベル(l)、タグ種別 (tg) を各行に付与する。

※ -Xlog の詳細：https://docs.oracle.com/javase/jp/11/tools/java.html#GUID-BE93ABDC-999C-4CB5-A88B-1994AAAC74D5
Copyright © NTT COMWARE CORPORATION 2022

8

JDK のトラブルシューティングの基本◼ ヒープダンプ◼ 取得時点での Java ヒープのスナップショット◼

.hprof ファイル◼

Java ヒープに含まれるオブジェクトやクラスの情報◼ どういった問題の際に確認するか◼

OutOfMemoryError の発生◼

メモリリーク◼

Full GC 多発◼ 確認のポイント◼

Java ヒープを占有しているオブジェクトの存在有無◼

GC により破棄されないオブジェクト間の参照関係

Eclipse Memory Analyzer の画面◼ おススメ解析ツール◼

Eclipse Memory Analyzer（MAT）◼

https://www.eclipse.org/mat/

Copyright © NTT COMWARE CORPORATION 2022

9

JDK のトラブルシューティングの基本◼ ヒープダンプ◼ 情報取得方法◼

◼

OutOfMemoryError 発生時に取得する場合
オプション名説明-XX:+HeapDumpOnOutOfMemoryError

OutOfMemoryError 発生時にヒープダンプを出力する。

任意のタイミングで取得する場合
コマンド

説明

$ jcmd <pid> GC.heap_dump

jcmd コマンドを用いてヒープダンプを出力する。
<pid>: Java プロセスID$ jmap –dump:format=b, file=<filename> <pid>jmap コマンドを用いてヒープダンプを出力する。
-dump:format=b: hprof のバイナリ形式で出力
file=<filename>: <filename> に出力<pid>: Java プロセスID

Copyright © NTT COMWARE CORPORATION 2022

10

JDK のトラブルシューティングの基本◼ スレッドダンプ◼ 取得時点での Java スレッド実行状態のスナップショット◼

各スレッドのスタックトレース◼

デッドロックの発生有無◼ どういった問題の際に確認するか
Java プロセスのハング◼
◼

Java スレッドで CPU 使用率の上昇など◼ 確認のポイント◼

複数のスレッドダンプを比較し、スレッドの状態遷移を確認◼

処理が進んでいないスレッドの有無◼

状態が Running のスレッドが想定していない処理で止まっていないか◼

処理がループしていないか

スレッドダンプ出力例（一部抜粋）"main" #1 prio=5 os_prio=0 cpu=40824.28ms elapsed=40.84s tid=0x00007ff468016000 nid=0x38421e
runnable [0x00007ff46f549000]
java.lang.Thread.State: RUNNABLE
at Loop.loop(Loop.java:3)
at Loop.main(Loop.java:7)
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.15/Native Method)…
at com.sun.tools.javac.launcher.Main.run(jdk.compiler@11.0.15/Main.java:179)
at com.sun.tools.javac.launcher.Main.main(jdk.compiler@11.0.15/Main.java:119)
Copyright © NTT COMWARE CORPORATION 2022

11

JDK のトラブルシューティングの基本◼ スレッドダンプ◼ 情報取得方法◼

数秒おきに複数回取得すること！
コマンド

説明

$ jcmd <pid> Thread.print

jcmd コマンドを用いてスレッドダンプを出力する。
<pid>: Java プロセスID$ jstack <pid>jstack コマンドを用いてスレッドダンプを出力する。
<pid>: Java プロセスID◼ おススメ解析ツール◼

Thread Dump Analyzer◼

https://github.com/irockel/tda

Thread Dump Analyzer の画面

Copyright © NTT COMWARE CORPORATION 2022

12

JDK のトラブルシューティングの基本◼ JDK Flight Recorder◼ Java AP や JVM のプロファイリングデータを収集するツール◼

GC ログやヒープダンプ、スレッドダンプで確認可能な情報相当のものを収集◼

JVM に組み込まれているため低負荷 ⇒ 利用可能ならば取得して損はない◼ OpenJDK で利用可能なバージョン◼

OpenJDK 8u262 以降のアップデートバージョン◼

OpenJDK 11 以降のメジャーバージョン◼ どういった問題の際に確認するか◼

様々な情報を確認できるため、前述した多くの問題の一次解析に有用◼ おススメ解析ツール◼

JDK Mission Control◼

https://jdk.java.net/jmc/8/

Copyright © NTT COMWARE CORPORATION 2022

13

JDK のトラブルシューティングの基本◼ JDK Flight Recorder◼ 情報取得方法◼

Java 起動オプション
オプション名説明-XX:StartFlightRecording

Java アプリケーション起動時に Flight Recorder の情報を出力する。オプション※で詳細設定可能。

※ オプションの詳細はリンク先の -XX:StartFlightRecording を参照
https://docs.oracle.com/javase/jp/11/tools/java.html#GUID-3B1CE181-CD30-4178-9602-230B800D4FAE◼

jcmd コマンド
コマンド

説明$ jcmd <pid> JFR.start

Flight Recorder を起動し情報収集を開始する。起動後に記録を開始した Flight Recorder の番号が出力される。
<pid>: Java プロセスID$ jcmd <pid> JFR.stop name=<number>

Flight Recorder を停止する。
<pid>: Java プロセスID<number>: Flight Recorder 番号$ jcmd <pid> JFR.dump name=<number>

記録した Flight Recorder の情報をダンプする。
<pid>: Java プロセスID<number>: Flight Recorder 番号

Copyright © NTT COMWARE CORPORATION 2022

14

JDK のトラブルシューティングの基本◼ コアダンプ◼ 実行中のプロセスのメモリスナップショット◼

スレッドのスタックトレースや JVM のネイティブレイヤを含めた詳細な情報を確認できる◼

コアダンプからヒープダンプ、スレッドダンプを抽出可能◼ どういった問題の際に確認するか◼

Java プロセスのクラッシュ◼

Java プロセスのハングでネイティブレイヤに問題がある場合◼ 確認のポイント◼

バックトレース、JVM 関数のコード、変数、ポインタの値 など◼ 情報取得方法◼

基本的にはクラッシュ時に生成される◼

OutOfMemoryError 発生時に取得する場合◼

オプション名説明-XX:+CrashOnOutOfMemoryError

OutOfMemoryError 発生時にコアダンプを取得する。

任意のタイミングで取得する場合
コマンド

説明

$ gcore -o <filename> <pid>gcore コマンドでコアダンプを取得する。
<pid>: Java プロセスID、<filename>: 出力先ファイルパス

◼ おススメ解析ツール◼

※解析には GDB と OpenJDK の専門的な知識が要求される

GDB、HSDB / JHSDBCopyright © NTT COMWARE CORPORATION 2022

15

JDK のトラブルシューティングの基本◼ その他◼ クラッシュレポート
JVM がクラッシュした際に出力されるレポート◼

hs_err_pid<pid>.log ファイル◼

◼

クラッシュの種類やエラーを引き起こしたスレッドのスタックトレースなどが記録◼

Java プロセスのクラッシュ解析に用いる◼ クラスヒストグラム◼

Java ヒープを使用しているクラス内訳が確認できる◼

jcmd <pid> GC.class_histogram で取得可能◼

Java ヒープの問題解析に用いる
Java ヒープを占有しているオブジェクトを簡単に確認可能◼

◼ クラスのロード / アンロード◼

クラスのロード / アンロード情報を出力◼

-XX:+TraceClassLoading / -XX:+TraceClassUnloading で取得可能◼

Metaspace や Compressed Class Space の OutOfMemoryError の問題解析に用いる◼ etc.

Copyright © NTT COMWARE CORPORATION 202216

トラブル事例紹介

Copyright © NTT COMWARE CORPORATION 2022

事例１：
長期安定化試験において Full GC 多発◼ システム構成◼ Oracle JDK 1.8.0_152 + WebLogic を使用◼ トラブル概要◼ システムの長期安定化試験中に Full GC が多発する事象が発生◼ Full GC 多発後も Java ヒープの使用量は下がらない◼ 長期安定化試験の負荷停止後には Full GC は発生しなくなるが、Java ヒープの使用量は下がりきってはいない様子

Copyright © NTT COMWARE CORPORATION 2022

18

事例１：
長期安定化試験において Full GC 多発◼ 解析アプローチ◼ Full GC が多発しているとの情報から Java ヒープの問題が考えられる◼ Full GC 後に Java ヒープの使用量が下がらないことから、
単純に Java ヒープ不足かメモリリークの疑いあり◼ まず GC ログの Java ヒープ傾向から GC チューニングで解消が見込める問題か確認する◼ リーク傾向がみられる場合にはヒープダンプで詳細を確認する◼ 確認すべきログ◼ GC ログ◼ Java ヒープの増加傾向を確認◼ Java ヒープの使用量が上昇し続けていればメモリリークの疑いあり◼ 想定より過剰な試験負荷を与えていないかも確認◼ ヒープダンプ◼ Java ヒープの内訳や詳細を確認◼ 特定のオブジェクトが Java ヒープを占有していないか

Copyright © NTT COMWARE CORPORATION 2022

19

事例１：
長期安定化試験において Full GC 多発◼ 解析（１/３）◼ GC ログの確認◼

GC ログから Java ヒープの増加傾向を確認◼

時間経過により Java ヒープ使用量が緩やかに増加している状況◼

Major GC や Full GC が発生しても Java ヒープ使用量が改善されていない◼

そのため Java ヒープの最大値まで使用量が上昇後、Full GC が多発する状況が続く⇒ メモリリークの疑いあり
GC ログを GCViewer で可視化した画面•

凡例Java ヒープの使用量が緩やかに増加Full GC が発生しても Java
ヒープ使用量が改善されない： Java ヒープの使用量： Full GC 発生タイミング
Copyright © NTT COMWARE CORPORATION 2022

20

事例１：
長期安定化試験において Full GC 多発◼ 解析（２/３）◼ ヒープダンプの確認
ヒープダンプ取得時の Java ヒープのオブジェクト内訳を確認する

◼

◼

◼

Eclipse Memory Analyzer の Overview や Leak Suspects レポートから確認可能◼

特定のオブジェクトが Java ヒープを占有していないか

特定のクラス（ユーザコード）のオブジェクトが Java ヒープの7割程度を占有

Eclipse Memory Analyzer の Leak Suspects

Leak Suspects からクラス毎のJava ヒープの占有率を円グラフで確認可能
7割程度を特定のクラスが占める状態であった

Copyright © NTT COMWARE CORPORATION 2022

21

事例１：
長期安定化試験において Full GC 多発◼ 解析（３/３）◼ ヒープダンプの確認
このクラスの詳細をオブジェクトの参照関係から深堀りすると、
セッション関係で使用されるクラスのオブジェクトが2万弱生成、保持されていた◼
◼

Eclipse Memory Analyzer の dominator_tree や Histgram から確認可能以上の Java ヒープの概況や占有しているオブジェクトのクラス名について問合せ元に連絡◼
◼

GC で解放されないオブジェクトを確認し、被疑のユーザコードに関連する情報を提示

Eclipse Memory Analyzer の dominator_tree

Overview で確認できたクラスのオブジェクトがJava ヒープを占有

オブジェクトの中に別のクラスのオブジェクトが大量に保持されていた
Copyright © NTT COMWARE CORPORATION 2022

22

事例１：
長期安定化試験において Full GC 多発◼ 対処と結果◼ 問合せ元へ解析結果の回答◼

該当オブジェクトが Java ヒープの7割程度を占有している状態が正しいか確認すること◼

正しくない場合、オブジェクトの解放漏れがないか確認すること◼

試験内容に不備（試験シナリオや試験負荷の妥当性）がないかも確認すること◼ 結果◼

問合せ元で該当オブジェクトのライフサイクルの確認を実施◼

該当オブジェクトは特定のオペレーション（ログアウトする処理）で解放されるように設計されていた◼

しかし長期安定化試験の試験シナリオにそのオペレーションが含まれていなかった◼

試験シナリオを見直したところ、オペレーション後の GC で Java ヒープがきちんと解放されるようになった◼ ポイント
◼

まず GC ログで AP の Java ヒープ傾向を確認する◼

メモリリークの解析はヒープダンプ解析が有用◼

オブジェクトの解放について AP 実装だけではなく試験シナリオを確認することも重要

Copyright © NTT COMWARE CORPORATION 2022

23

事例２：
Java プロセスのクラッシュ◼ トラブル◼ 基盤構築作業中に Java プロセスが異常終了でクラッシュ◼ AP サーバの Java プロセス死活監視で発覚◼ システム構成サーバのうち２台だけ発生◼ アプリケーションは未デプロイで Tomcat が起動しているだけで無操作

アプリケーション（未デプロイ）Tomcat

収集した情報AP ログ（catalina.out）
GC ログ
JDK Flight Recorder

OpenJDK 11.0.8

コアダンプ（クラッシュ時に生成）

RHEL

システムスタック

Copyright © NTT COMWARE CORPORATION 2022

24

事例２：
Java プロセスのクラッシュ◼ 解析アプローチ◼ Java プロセスがクラッシュしているので JVM の問題と想定◼ 通常 Java 実装が原因でクラッシュしない◼ OpenJDK バグの可能性◼ クラッシュレポート（hs_err）とコアダンプを解析◼ JVM の何の処理で問題が起きているかを確認◼ 今回は hs_err ファイル無し◼ 既知バグに該当しないかをチェック◼ JDK Bug System <https://bugs.openjdk.org/>

Copyright © NTT COMWARE CORPORATION 2022

25

事例２：
Java プロセスのクラッシュ◼ 問題発生時刻の状況確認◼ 問題発生時は無操作にも関わらずクラッシュが発生◼ アイドリング状態なのにクラッシュするのは考えにくい◼ 何かしらトリガとなる様な操作を本当にしていないのか？
◼ 外部の死活監視ログから 0:00 ちょうどから無応答に◼ 偶然にしてはきりがいい時間で都合よく見える◼ 何か実行される設定があるのでは？
◼ GC ログと JDK Flight Recorder のログローテーションを実行することが判明◼ 問合せ元に確認したところ 0:00 にローテーションを実行すると回答あり◼ Java 起動オプションからもローテーションの設定が見て取れた◼ Unified Logging か JDK Flight Recorder(JFR) の実装が怪しいのでは？
0:00 に cron によってログローテーションが実行

cron
jcmd

GC ログ

GC.rotate
JFR.dump

JFR

JVM

Copyright © NTT COMWARE CORPORATION 2022

26

事例２：
Java プロセスのクラッシュ◼ コアダンプ解析◼ まずは解析環境構築を実施 ※詳細は省略、ポイントだけ◼ gdb や OpenJDK および関連パッケージの debuginfo のインストール◼ 実行環境と違う環境で解析する場合は OS とパッケージを完全一致させること◼ gdb でコアダンプを開いたところ SIGABRT が発生してた◼ $ gdb java coredump◼ Program terminated with signal SIGABRT, Aborted.
◼ JVM のシグナルハンドラがシグナルを検知することをヒントに被疑スレッドを特定◼ JVM 実装の EdgeUtils::field_name_symbol 関数でクラッシュを確認◼ ソースコードパスから JFR のリークプロファイラ実装であることも分かった#20 <signal handler called>#21 EdgeUtils::field_name_symbol (edge=...) at src/hotspot/share/oops/fieldStreams.hpp:53#22 0x00007f044ac9781b in get_field_info_id (edge=...)
at src/hotspot/share/jfr/leakprofiler/checkpoint/objectSampleWriter.cpp:303#23 add_reference_info (parent_id=232, id=<optimized out>, current=0x7f0410daee28)
at src/hotspot/share/jfr/leakprofiler/checkpoint/objectSampleWriter.cpp:550#24 ObjectSampleWriter::write (this=this@entry=0x7f0419579680, edge=edge@entry=0x7f0410daee28)
at src/hotspot/share/jfr/leakprofiler/checkpoint/objectSampleWriter.cpp:573#25 0x00007f044ac982d9 in ObjectSampleWriter::operator() (this=this@entry=0x7f0419579680, e=...)
at src/hotspot/share/jfr/leakprofiler/checkpoint/objectSampleWriter.cpp:637…省略
クラッシュ被疑スレッドのバックトレース抜粋

Copyright © NTT COMWARE CORPORATION 2022

27

事例２：
Java プロセスのクラッシュ◼ 既知バグ調査◼ EdgeUtils::field_name_symbol() で検索すると同一事象がヒット◼ https://bugs.openjdk.org/browse/JDK-8239497◼ Flight Recorder 実装で扱う関数に想定していない配列が渡されることがある◼ 非配列であることを前提に評価される処理があるためクラッシュに繋がる◼ OpenJDK 11.0.10 で修正◼ クラッシュしたアプリケーションは 11.0.8 なので修正されておらず

影響バージョンと修正バージョン

バックポートによる修正バージョン
Copyright © NTT COMWARE CORPORATION 2022

28

事例２：
Java プロセスのクラッシュ◼ 対処◼ OpenJDK を 11.0.10 以降のバージョンにアップデート◼ 基本的には最新バージョンへのアップデートを推奨◼ アップデート後は全台の Tomcat で再発せず、解決◼ ポイント◼ OpenJDK のクラッシュは hs_err とコアダンプで解析◼ 被疑スレッドの実行処理を JBS で検索するまではできるとよい◼ 状況によっては解析が難しい場合もあるのでベンダに問い合わせるのも手◼ OpenJDK 11 以降で JFR を使用している場合にクラッシュする可能性あり◼ JDK 11 のクラッシュは珍しいため共有した次第◼ JDK の更新（アップデートバージョン）はすべき

Copyright © NTT COMWARE CORPORATION 2022

29

事例３：
Compressed Class Space 起因の OOME 発生◼ トラブル◼ 長期安定化試験実施中に OutOfMemoryError(OOME) が発生◼ java.lang.OutOfMemoryError: Compressed class space◼ メモリ割り当て設定を確認しても不足している様子は見えない◼ Java ヒープ 6GB◼ Metaspace 512MB, 内 Compressed Class Space(CCS) 128MB

収集した情報Spring Framework 4
AP ログ （クラスロード・アンロード含む）

OpenJDK 1.8.0

GC ログ
ヒープダンプ（OOME 発生時に取得）

Linux OSjstac –gc（事象発生時に手動取得）

システムスタック
Copyright © NTT COMWARE CORPORATION 2022

30

事例３：
Compressed Class Space 起因の OOME 発生◼ 解析アプローチ◼ まずは GC ログから Metaspace/CCS の利用状況をチェック◼ リークし続けている傾向が見えないか確認◼ 単純に不足している様子であれば割り当てを増やす◼ Metaspace/CCS のメモリリークの傾向が見えたら原因を探す◼ CCS はクラスメタデータを保持する領域◼ 通常は安定するものだが、クラスの動的ロードが大量に行われていると増加◼ 動的クラスを作成する実装（主にフレームワークなど）が怪しい◼ クラスロード・アンロード情報から原因を特定

Copyright © NTT COMWARE CORPORATION 2022

31

事例３：
Compressed Class Space 起因の OOME 発生◼ GC ログ解析（１/２）◼ Java ヒープは安定しているが、Metaspace 起因の Full GC が頻発◼ Java ヒープは足りているものの Major GC/Full GC が頻発◼ Metaspace 起因の Full GC だけでも数千回発生
GC ロググラフ
X軸：時間（30分間表示）
Y軸：Java ヒープ使用量（最大 6GB）

凡例：Java ヒープの使用量：Old 領域使用量：Full GC 発生タイミング：Major GC 発生タイミング

Copyright © NTT COMWARE CORPORATION 2022

32

事例３：
Compressed Class Space 起因の OOME 発生◼ GC ログ解析（２/２）◼ Metaspace(CCS 含む)の使用量が最大サイズ間際まで消費◼ GCViewer では Metaspace の詳細は見れないので生ログを確認◼ Metaspace を 95％ 程度消費し続けている
GC ログ抜粋※見やすさのため整形済み

XXXX-XX-XXTXX:XX:XX.XXX+0900: 181275.052:[Full GC (Metadata GC Threshold) XXXX-XX-XXTXX:XX:XX.XXX+0900: 181275.053:[CMS: 1710842K->505812K(4194304K), 3.8019184 secs] 2757071K->505812K(6081792K),[Metaspace: 461735K->461735K(485376K)], 3.8027842 secs] [Times: user=3.80 sys=0.00,
real=3.81 secs]◼ CCS の使用量も最大サイズ間際まで消費◼ あらためて負荷発生時の jstat -gc 情報を取得◼ CCS にフォーカスしても 96% 程度消費し続けている
jstat -gc 結果抜粋

※見やすさのため整形済み

XXXX/XX/XX XX:XX:XX ...省略 MC
MU
CCSC
CCSU
...省略
XXXX/XX/XX XX:XX:XX ...省略 483004.0 458211.1 131072.0 126672.7 ...省略※ MC: Metaspace 容量(KB)

MU: Metaspace 使用量(KB) CCSC: CCS 容量(KB)

CCSU: CCS 使用量(KB)

Copyright © NTT COMWARE CORPORATION 2022

33

事例３：
Compressed Class Space 起因の OOME 発生◼ クラスロード・アンロード情報収集◼ Metaspace/CCS が増えている場合は動的クラスがガンガン生成されていることが多い◼ クラスのロード・アンロードログを追跡することに◼ Java 起動オプションに 以下を付与◼ -XX:+TraceClassLoading と -XX:+TraceClassUnloading◼ AP ログを見ると大量にロードされているクラスがあった！

◼ spel.ExXXXX というクラスが大量にロードされていた◼ 24万程度ロードされる一方、ほとんどアンロードされず
AP ログ抜粋（クラスロード）[Loaded spel.Ex242991 from __JVM_DefineClass__][Loaded spel.Ex242992 from __JVM_DefineClass__][Loaded spel.Ex242993 from __JVM_DefineClass__][Loaded spel.Ex242994 from __JVM_DefineClass__][Loaded spel.Ex242995 from __JVM_DefineClass__][Loaded spel.Ex242996 from __JVM_DefineClass__]

Copyright © NTT COMWARE CORPORATION 2022

34

事例３：
Compressed Class Space 起因の OOME 発生◼ spel.exXXXX クラスの調査◼ ヒープダンプから参照関係にあるクラスを確認◼ Spring Framework 関係のクラスから参照されていた◼ org.springframework.expression.spel.CompiledExpression◼ 調べたところ Spring Expression Language(SpEL) 式に関するクラス◼ Spring Framework ついては専門領域外なので社内の有識者に確認◼ SpEL コンパイラの動的クラス生成であることが判明◼ SpEL 式利用時に SpEL コンパイラが有効になっていると動的クラスが生成◼ 原因切り分けのため SpEL コンパイラを無効化した◼ enableSpringELCompiler を false に◼ 再度試験したところ OOME が発生しなくなった！

◼ SpEL コンパイラの利用が原因であることが判明

Copyright © NTT COMWARE CORPORATION 2022

35

事例３：
Compressed Class Space 起因の OOME 発生◼ SPEL 設定の確認（１/２）※社内有識者の見解◼ Thymeleaf（画面生成）のキャッシュ機能と SpEL コンパイラの不具合が組み合わさったことで発生した事象◼ 試験負荷によって大量の SpEL 動的クラスが生成される状況◼ Thymeleaf は SpEL 式ごとに SpEL オブジェクトを生成しキャッシュ◼ SpEL オブジェクトは閾値（100）を超えると動的クラスを生成◼ Thymeleaf のキャッシュは閾値（500）を超えると順次破棄される◼ 試験負荷が大きいことで動的クラス生成が繰り返される◼ 100を超えたユーザ数で大量の式が埋め込まれた画面に繰り返しアクセス◼ キャッシュの蓄積と動的クラス生成が進むがすぐにキャッシュが破棄◼ 破棄されたキャッシュと同じ式の動的クラス生成が繰り返される◼ これにより Metaspace/CCS が圧迫される状況に

Copyright © NTT COMWARE CORPORATION 2022

36

事例３：
Compressed Class Space 起因の OOME 発生◼ SPEL 設定の確認（２/２）※社内有識者の見解◼ SpEL の動的クラスが破棄されにくい仕様◼ SpEL クラスは単一のクラスローダによってロードされる◼ ロードされたクラスが全てアンロードされる状況にならないと解放されない◼ バグとして Spring Framework 5 以降で順次アンロードされるように修正◼ Spel Expressions leaks classes [SPR-15460]◼ https://github.com/spring-projects/spring-framework/issues/20020

Copyright © NTT COMWARE CORPORATION 2022

37

事例３：
Compressed Class Space 起因の OOME 発生◼ 対処◼ SpEL コンパイラを無効化◼ SpEL コンパイラは大量の式があるとその恩恵を受けにくい場合も◼ Thymeleaf のデフォルトは SpEL コンパイラ無効化◼ 無効化して要求性能を満たすことを試験して確認し解決◼ ポイント◼ Metaspace/CCS 起因の OOME も発生することがある◼ Metaspace/CCS の解析は容易ではない◼ Java ヒープと違って CCS の内容を確認する方法が少ない◼ クラスロード＆アンロードログから探るのも一つの手◼ フレームワーク側の既知の不具合も探してみることも重要◼ 動的クラスの生成などはユーザコードで行うことは稀なためCopyright © NTT COMWARE CORPORATION 2022

38

まとめ

Copyright © NTT COMWARE CORPORATION 2022

まとめ
◼ トラブルが発生する前に解析に有用な情報は取得するようにしておく◼ GC ログ：GC 頻発による AP の性能劣化、Java ヒープに関するエラーが発生◼ ヒープダンプ：メモリリーク、OutOfMemoryError◼ スレッドダンプ：Java プロセスのハング◼ JDK Flight Recorder：色々な問題の一次解析に適している◼ コアダンプ：Java プロセスのクラッシュ◼ 各事例のポイントおさらい◼ 事例１：長期安定化試験において Full GC 多発◼ 試験でのトラブルは試験シナリオも注視しよう◼ 事例２：Java プロセスのクラッシュ◼ JDK の更新（アップデートバージョン）は大事◼ 事例３： Compressed Class Space 起因の OOME 発生◼ フレームワークの設定見直しや既知バグを探すことも大事
Copyright © NTT COMWARE CORPORATION 2022

40

Q＆A

Copyright © NTT COMWARE CORPORATION 2022

41