Upgrade to Pro — share decks privately, control downloads, hide ads and more …

JJUG CCC 2021 Spring-Resolving OOME with JFR

JJUG CCC 2021 Spring-Resolving OOME with JFR

JJUG CCC 2021 Spring の「JFR などのツールを用いて FullGC や OOME の原因を特定する流れ」の登壇資料です。

Takaichi00

May 07, 2021
Tweet

More Decks by Takaichi00

Other Decks in Technology

Transcript

  1. JFR などのツールを用いて FullGC や OOME の原因を特定する流れ
    # jjug #jjug_ccc
    髙市 智章 (Tomoaki Takaichi)
    May, 23, 2021 JJUG CCC 2021 Spring

    View full-size slide

  2. 自己紹介
    @Takaichi00
    tomoaki.takaichi.5
    ・髙市 智章(タカイチ トモアキ)
    ・Java でのシステム開発
    ・CI / CD
    ・Container / k8s
    ・アジャイル開発実践
    共著: クリーンなコードへの
    SonarQube即効活用術
    www.amazon.co.jp/dp/B086ML43DH

    View full-size slide

  3. ❏ 以前、検証では成功した Java のプログラムが商用で失敗するという
    ことを経験した
    ❏ PreparedStatement / ResultSet の close 忘れによりE (OOME) が
    発生してしまうことが原因だった
    本日お話すること
    参考: 【JUGナイトセミナー】検証では成功した Java のパッチが商用でコケた件

    View full-size slide

  4. ❏ 前回事例を発表した LT では、プログラムに問題がありそ
    うな箇所をあらかた特定できていたため、GC Viewer を
    用いてトライアンドエラーで問題を解決できた
    ❏ しかし Java アプリケーションを運用する上で実際に発生
    する問題には、原因に見当がつかないものも多いのでは
    本日お話すること

    View full-size slide

  5. ❏ 今回ではこの問題に対して「もし原因の見当すらついていな
    かった場合どのように対処するか?」という観点で、JFR (JDK
    Flight Recorder) などのツールを用いながら問題解決をしてい
    く流れを発表する
    ❏ 以下のような方を対象に、この発表が参考になれば幸い
    ❏ JFR などのツールは聞いたことがあるが使ったことがない、これから使っ
    てみたいので概要や使い方を知りたいという方
    ❏ プログラミング言語としての Java だけではなく、JVM / GC / Heap /
    Stack / Thread などの技術にも触れてみたいという方
    本日お話すること

    View full-size slide

  6. ❏ 発表内容には誤りが無いよう、様々な文献などを参考にし
    て最善を尽くしておりますが、まだまだ知識が足りないと
    感じています
    ❏ もし発表内容に誤りがある / もっと効率的な調査方法や
    ツールがあるといった場合には、その旨をご連絡・ご発信
    いただけますと幸いです
    発表内容にあたって
    https://www.oreilly.co.jp/books/images/picture_large978-4-87311-718-8.jpeg

    View full-size slide

  7. 問題が発生した事例の紹介

    View full-size slide

  8. ❏ 今回のサンプルアプリケーションは Github にて公開中
    ❏ Java と Docker の環境があれば再現が可能
    問題が発生したアプリケーションのサンプル
    Takaichi00 / jfr-sample: https://github.com/Takaichi00/jfr-sample

    View full-size slide

  9. ❏ 以下のような java のプログラムを作成
    問題が発生したアプリケーション
    id name address
    1 aaa NULL
    2 bbb NULL
    ... … ...
    name register_
    event
    aaa 1
    aaa 2
    bbb 1
    .jar
    ① `address` が NULL の一覧取得
    ② `name` に対応する `register_event` を取得 / 判定処理
    insert.sql
    ④ TABLE_A に `name` に対
    応する `address` を insert
    する SQL ファイルを作成
    TABLE_A
    TABLE_B
    register_
    event
    address
    1 123
    2 456
    ... ...
    TABLE_C
    ③ `register_event` に対応する
    `address` を取得 / 判定処理

    View full-size slide

  10. 問題の実装コードと実行コマンド
    TEBLE_A から SELECT したデータ
    を List に格納
    List の数だけ TEBLE_B に対して
    SELECT を実行
    TEBLE_B で取得できた結果の数だ
    け、再度 TEBLE_C に対して
    SELECT を実行
    (※) 今回は再現のため、簡略的に
    TABLE_C ではなく TABLE_B に
    SELECT を実行

    View full-size slide

  11. ❏ ローカル PC (メモリ 16GB) から、検証用のデータが入っ
    た検証用 DB へ向けてこのパッチを起動したところ、問題
    なく実行が完了した (データ量は数十件程度)
    検証の構成では成功
    検証環境
    成功
    メモリ: 16GB

    View full-size slide

  12. ❏ 商用環境では VM 上 (メモリ 1GB) で作成したパッチを実
    行した。しかし処理が全然完了しなかった
    ❏ 商用のデータ量は検証環境よりは多いが、たかだか1万件
    未満程度のもの
    商用環境では失敗
    商用環境
    失敗
    メモリ: 1GB

    View full-size slide

  13. ❏ java -jar コマンド実行時の引数に -Xlog:gc* を追加して
    GC ログの詳細を表示してみる
    ❏ すると FullGC が多発していることがわかった
    GC ログを出してみる
    $ java -Xlog:gc* -jar hoge.jar
    ...
    [81.318s][info][gc ] GC(29) Pause Full (G1 Evacuation Pause)
    ...
    [81.318s][info][gc,cpu ] GC(29) User=0.05s Sys=0.00s Real=0.02s
    ※ Java11, GC は G1GC を使用

    View full-size slide

  14. ❏ JVM にはエルゴノミクスというプロセスがあり、マシンのスペックに
    応じてヒープサイズが自動決定される
    ❏ デフォルトでは以下の設定となっている
    ヒープオプションを追加する
    初期ヒープ・サイズ 物理メモリーの 1/64 (最大1GB)
    最大ヒープ・サイズ 物理メモリの 1/4 (最大1GB)
    ❏ 今回 jar を実行した商用環境では、メモリが 1GB となっていたため、
    最大でも250 MB 程度しかヒープを使うことができない状態
    ❏ 一時対処として jar 実行時に、-Xms512M -Xmx512M のようにヒー
    プサイズを設定することで、時間はかかったが処理を完了させること
    ができた

    View full-size slide

  15. ❏ 後日コードレビューにより、PreparedStatement /
    ResultSet の close 忘れが発覚
    ❏ 本当にこれらが原因なのか検証するため、まずは GC
    Viewer を用いて簡易的に解析
    そもそも実装コードが悪い

    View full-size slide

  16. ❏ GC ログから、GC の発生やそれに伴うヒープの推移など
    が視覚的に表示できるツール
    ❏ もともと tagtraum 社によって開発されていたが、2008
    年で開発がストップされており、現在は個人の方が開発を
    続けているツール
    GC Viewer とは
    GC Viewer のダウンロード:
    https://github.com/chewiebug/GCViewer/wiki/Changelog

    View full-size slide

  17. ❏ 似たようなプログラムを実装し、ヒープサイズ 20MB と指定
    し、GC ログを出力するようにして実行した結果、処理が進
    むに連れ FullGC が発生して最終的に OutOfMemoryError
    が発生した (データ量約1万件)
    問題のプログラムを GC Viewer を用いて解析
    $ java -Xlog:gc:./gc.log \
    -Xlog:gc* \
    -Xms20M -Xmx20M -jar hoge.jar
    GC ログをファイルに出力して実行し、GC
    Viewer からログファイルを読み込む

    View full-size slide

  18. ❏ PreparedStatement / ResultSet を close するよう処理
    を修正したところ FullGC は発生せず適切にメモリが開放
    されて処理が継続できた (データ量約1万件)
    解決方法

    View full-size slide

  19. 問題が発生した事例のまとめ
    ❏ ヒープサイズは指定して実行しないと、マシンによって実
    行結果に差異が出る可能性 (エルゴノミクス)
    ❏ DB 接続処理などで実施すべき close 処理は怠らない
    ❏ できるなら商用環境のデータ量でテストを実施する
    ❏ GC ログ, GC Viewer を用いてアプリケーションの内部状
    態を手軽に確認できる

    View full-size slide

  20. もし問題点がわからなかったら
    どのように対処するか?

    View full-size slide

  21. ❏ プログラムに問題がありそうな箇所をあらかた特定できていたため、
    GC Viewer を用いてトライアンドエラーで問題を解決できた
    ❏ しかし実際に発生する問題には、原因に見当がつかないものも多い
    ❏ GC log, GC Viewer だけでは原因追求は難しい
    ❏ そこで「もし原因の見当すらついていなかった場合どのように
    対処するか?」という観点でこのプログラムを解析していく
    問題の特定をどのようにするか

    View full-size slide

  22. OutOfMemoryError のメッ
    セージを確認する

    View full-size slide

  23. ❏ アプリケーションの実行結果では「Exception in thread
    "main" java.lang.OutOfMemoryError: Java heap space」
    というエラーメッセージが表示された
    ❏ よって今回では Heap Memory がいっぱいになったということが
    わかる
    OOME が発生した実行結果のログを確認する
    アプリケーションの実行結果:

    View full-size slide

  24. ❏ しかしこの情報だけでは、単に使用中のオブジェクトが多すぎ
    てヒープに収まらなくなったのか、不使用になったオブジェク
    トを開放せず、新しいオブジェクトの割当を続けていることが
    原因なのかがわからない
    ❏ 単にヒープサイズを拡大したら問題なく動いた、というのは
    本質的な解決策ではない
    OOME が発生した実行結果のログを確認する

    View full-size slide

  25. 補足: OOME の種類
    Exception in thread "main" java.lang.OutOfMemoryError:
    # Heap Memory がいっぱいの場合
    “Java heap space”
    # Native Memory がいっぱいの場合
    “unable to create new native thread”
    # Metaspace がいっぱいの場合
    “Metaspace”
    # GC に時間がかかりすぎている場合
    “GC Overhead limit exceeded”
    … などなど
    Java Platform, Standard Editionトラブルシューティング・ガイド, 3.2 OutOfMemoryError例外の理解:
    https://docs.oracle.com/javase/jp/8/docs/technotes/guides/troubleshoot/memleaks002.html

    View full-size slide

  26. JFR (JDK Flight Recorder)
    での解析

    View full-size slide

  27. ❏ JFR (JDK Flight Recorder) とは、OpenJDK 11 から無
    償利用できるようになった、Java アプリケーションの障
    害分析ツール
    ❏ 現在では OpenJDK 8 update 262 にバックポートされている
    ❏ CPU / ヒープ / GC / Thread … など、Java アプリケー
    ションに関する様々なメトリクスを確認することができる
    JFR (JDK Flight Recorder) とは

    View full-size slide

  28. ❏ 実行時に “-XX:StartFlightRecording=parameter=value” オ
    プションを指定することで JFR を有効にすることが可能
    ❏ 以下のコマンドの例では、アプリケーション終了後に .jfr をダ
    ンプルすることができる
    JFR を有効にしてアプリケーションを起動する
    オプションの詳細 (日本語):
    https://koduki.github.io/docs/book-introduction-of-jfr/site/03/01-recording-jfr.html
    $ java \
    -XX:StartFlightRecording=\
    dumponexit=true,\ # JVM プロセスがシャットダウンした時にファイルにダンプする
    filename=./output/jdbc-bad-sample-FULLGC.jfr,\
    -Xms20M -Xmx20M -jar ./target/jdbc-bad-sample-FULLGC.jfr

    View full-size slide

  29. ❏ .jfr ファイルを取得するには、Java の実行オプションで
    指定する以外にも、 jcmd コマンドを利用した以下のよう
    な方法がある
    補足: JFR の取得方法
    $ java -XX:StartFlightRecording -Xms20M -Xmx20M -jar ./target/jdbc-bad-sample-FULLGC.jar
    # 1分間の間 JFR の記録を実行し、ファイルに出力する
    $ jcmd JFR.start duration=1m filename=recording.jfr
    # JFR の記録の実行中にデータをファイルに書き込み、記録の実行を継続する
    $ jcmd JFR.dump filename=recording.jfr
    Java Platform, Standard Edition Java Flight Recorderコマンド・リファレンス, 2 診断コマンド・リファレン
    ス:https://docs.oracle.com/javacomponents/jp/jmc-5-5/jfr-command-reference/diagnostic-command-reference.htm

    View full-size slide

  30. ❏ 作成された .jfr ファイルは JMC (JDK Mission Control)
    を使って視覚的に確認することができる
    ❏ JMC のダウンロードは Oracle の公式サイト や 各 JDK
    のディストリビューションから可能
    ❏ Oracle:
    (https://www.oracle.com/java/technologies/javase/products-jmc8-downloads.html)
    ❏ AdoptOpenJDK: (https://adoptopenjdk.net/jmc.html)
    ❏ Zulu: (https://jp.azul.com/products/zulu-mission-control/)
    JMC (JDK Mission Control) で結果を解析する
    https://avatars.githubusercontent.com/u/34046054?s=200&v=4

    View full-size slide

  31. ❏ JMC を起動し、「ファイル(F)」→「ファイルを開く」か
    ら、生成した jdbc-bad-sample-FULLGC.jfr を選択する
    と、分析結果が表示されていることを確認できる
    FullGC が発生するアプリケーションを JFR / JMC で で解析

    View full-size slide

  32. JMC で Java アプリケーションを解析する
    ❏ 問題なありそうな箇所は、赤い
    「!」アイコン で表示されている
    ❏ まずは左メニューから「アウトラ
    イン」→「Java アプリケーショ
    ン」を選択し、アプリケーション
    の解析結果を確認する

    View full-size slide

  33. JMC で Java アプリケーションを解析する
    ❏ 「Java アプリケーショ
    ン」ではアプリケーショ
    ンの全体概要を表示する
    ことが可能
    ❏ スレッド / CPU 使用率
    / ヒープ使用率 / GC 起
    因等によるユーザーコー
    ドの停止時間 などを確
    認することができる

    View full-size slide

  34. JMC で Java アプリケーションを解析する
    スレッド情報: main スレッドでプ
    ロファイリングが実施されてい
    る。対象のスレッドはクリックで
    選択可能
    ヒープ使用量: 徐々にヒープが上昇
    し続けている
    停止: 実行時間と共に、GC 起因等に
    よるユーザーコードの停止時間が長
    くなってきている

    View full-size slide

  35. JMC で Java アプリケーションを解析する
    ヒープ: 時間とともに上昇を続けて
    おり、GC が発生しても適切にメモ
    リが開放されていない
    ❏ 「メモリー」では、マシン全体
    のメモリサイズ、使用されてい
    るヒープ、GC の発生頻度と時
    間などが確認できる
    ❏ ヒープ統計を有効にしていない
    ので、ヒープに関する詳細な統
    計情報は表示されていない
    ガベージ・コレクション (GC): 時
    間とともにに GC にかかる時間が
    増加している

    View full-size slide

  36. JMC で Java アプリケーションを解析する
    ❏ 「メモリー」→ 「ライブ・オ
    ブジェクト数」から、GC の対
    象外となるオブジェクト
    (OOME の原因となりそうなオ
    ブジェクト) を確認することが
    できる
    ❏ しかしヒープ統計を有効にし
    ていないので、詳細な統計情
    報は表示されていない
    ライブオブジェクトとは... ガベージコレクタの仕組みを理解する:
    https://www.atmarkit.co.jp/ait/articles/0404/02/news079.html

    View full-size slide

  37. JMC で Java アプリケーションを解析する
    ❏ 「JVM 内部」→ 「ガベージコ
    レクション」から、GC の統計
    情報を取得することができる
    GC ID / コレクタ名: “G1Full” が
    表示されており、Full GC が頻発し
    ている
    最長の一時休止 / 一時停止合計: 実
    行時間の経過に伴い、Full GC が頻
    発しているためアプリケーション
    の休止時間も増加傾向にある

    View full-size slide

  38. ここまでのまとめ
    ❏ アプリケーションの実行時間が進むにつれ...
    ❏ FullGC が徐々に発生し始め、頻度が高くなる
    ❏ ヒープ使用率が徐々に増加している
    ❏ アプリケーションの休止時間が多くなる
    ❏ しかし原因の特定までは至っていない

    View full-size slide

  39. ❏ JFR / JMC を用いた解析で、徐々にヒープ使用率が上昇し
    ていることがわかる
    ❏ 単にヒープサイズが足りないのが原因ではなさそう。
    ヒープを増やしても問題の本質的な解決になならない
    ❏ 使用されているヒープのうち、何がヒープ上昇の原因と
    なっているかを追求する
    Next Action

    View full-size slide

  40. ヒープダンプを取得し
    Memory Analyzer で解析

    View full-size slide

  41. ❏ ヒープダンプを取得することで、ヒープの内訳を確認する
    ❏ ヒープダンプの取得方法は複数あるが、まずは OOME 発
    生時にヒープダンプを生成してくれる
    “-XX:+HeapDumpOnOutOfMemoryError” をつけて実
    行してみる
    ヒープダンプ を取得する
    $ java \
    -XX:+HeapDumpOnOutOfMemoryError \
    -XX:HeapDumpPath=./output \
    -Xms20M -Xmx20M -jar ./target/jdbc-bad-sample.jar

    View full-size slide

  42. ❏ 作成された .hprof ファイルは Memory Analyzer で解析す
    ることができる
    ❏ Memory Analyzer は Eclipse Foundation のページ
    (http://www.eclipse.org/mat/) からダウンロードが可能
    .hprof ファイルを Memory Analyzer で解析する
    http://www.eclipse.org/mat/

    View full-size slide

  43. ❏ 「File」→「Open File」から、先程作成された .hprof ファ
    イルを開くと、以下のように解析された画面が表示される
    ❏ 円グラフの部分をクリックすると、どのオブジェクトがどの
    くらいの割合を占めているかを確認することができる
    .hprof ファイルを Memory Analyzer で解析する

    View full-size slide

  44. ❏ このヒープダンプが取られているのは OOME 発生時なので、一番割合
    を占めているものが怪しい
    ❏ 一番割合が多い部分をクリックすると、
    com.mysql.cj.jdbc.ConnectionImpl との記載がある。よって mysql
    の接続処理に問題がありそうという目星をつけることができる。
    .hprof ファイルを Memory Analyzer で解析する

    View full-size slide

  45. ❏ 「Actions」→「Histogram」を選択すると、Class の一
    覧と Object 数、Object 単体のサイズ (Shallow
    Heap)、Object が持つ他の Object を含めたサイズ
    (Retained Heap) がリストで表示される
    .hprof ファイルを Memory Analyzer で解析する

    View full-size slide

  46. .hprof ファイルを Memory Analyzer で解析する
    ❏ Retained Heap の多い順にリストを並び替えると
    java.lang.Object, CopyOnWriteArrayList の下に
    com.mysql.cj.jdbc.~ のクラスが続いている
    ❏ ここから MySQL の Connection 周りで大きく heap を使ってい
    ることがわかる

    View full-size slide

  47. .hprof ファイルを Memory Analyzer で解析する
    ❏ 一番 heap を使っている java.lang.Object の "Merge
    Shortest Path to GC Roots" を開くと、生存している
    (GC の対象外となった) Object と、その Object が参照
    している Object 群を階層構造で表示できる

    View full-size slide

  48. .hprof ファイルを Memory Analyzer で解析する
    ❏ Main Thread を expand していく
    と、”com.mysql.cj.jdbc.~” の
    Object が大量に存在していること
    がわかる
    ❏ ”ConnectionImpl”
    ❏ “ClientPreparedStatement”
    ❏ “ResultSetImpl”
    ❏ よって MySQL DB へ接続する処理
    で、Connection 処理が適切に
    close されていないのでは? とい
    う仮説をたてることができる

    View full-size slide

  49. 仮説で浮かび上がった問題を解
    消し、再度解析を実行する

    View full-size slide

  50. ❏ 問題が発生したアプリケーションのコードの
    PreparedStatement, ResultSet が利用されている部分
    を確認すると、確かに close 処理が記述されていない
    ❏ close 処理を実施したうえで、再度解析を実施してみる
    OOME の原因を解消して再度解析する
    PreparedStatement と
    ResultSet の close 処理
    をそれぞれ記載

    View full-size slide

  51. ❏ PreparedStatement と ResultSet の close 処理を行った
    アプリケーションを実行すると、問題なく処理が完了した
    ❏ JFR で解析してみると以下のように、適切にメモリが開放さ
    れていることがわかる
    OOME の原因を解消して再度解析する
    OOME 発生時に表示されていた赤い
    「!」マークも今回は表示されていない
    ※ 「環境」→「プロセス」に表示されている
    ものはローカル PC の CPU 使用率に起因し、
    マシンで実行している他のアプリケーション
    の影響も受けるので今回は対象外と考える

    View full-size slide

  52. ❏ 「ガベージ・コレクション」を確認しても、FullGC は発
    生しておらず、休止期間も低下していることがわかる
    OOME の原因を解消して再度解析する

    View full-size slide

  53. ❏ OOME は発生しないので、前回とは別の方法でヒープダン
    プを取得する
    ❏ 処理の後半で jmap コマンドを実行し、ヒープダンプを取
    得して Memory Analyzer で解析する
    # ヒープダンプの生成前に FullGC を実施
    $ jmap -dump:live,file=
    # 以下のコマンドでも ヒープダンプを取得可能
    $ jcmd GC.heap_dump
    OOME の原因を解消してヒープダンプを取得

    View full-size slide

  54. ❏ 取得できた .hprof ファイルを Memory Analyzer で開いてみると、
    ヒープ全体のサイズは 6.6MB と 20MB の上限まで余裕があり、円グ
    ラフで一番割合が多い部分は java.lang.Thread (main) となっている
    ❏ OOME 発生時に Heap の多くの割合を占めていた
    com.mysql.cj.jdbc.ConnectionImpl は見られない
    OOME の原因を解消してヒープダンプを取得
    ※ 灰色の部分は Remainder とい
    う、上位の割合を占めないその他
    の Heap を合計したもの

    View full-size slide

  55. ❏ 前回同様「Histgram」から一番 heap を使っている
    java.lang.Object の "Merge Shortest Path to GC Roots" を
    開いて見てみても、”com.mysql.cj.jdbc” のオブジェクトは見
    られない → OOME の問題は解消と判断できる
    OOME の原因を解消して ヒープダンプ を取得

    View full-size slide

  56. ここまでのまとめ
    ❏ JFR を有効にし、JMC を用いて解析を行うことでアプリ
    ケーションがどのようなヒープ、GC の傾向によって
    OOME エラーが発生したかを把握
    ❏ OOME 発生時にヒープダンプを取得することで、 OOME
    の原因となっているオブジェクトを特定
    ❏ 原因と思われる箇所を修正し、再度同様の解析を実施して
    問題が解消されていることを確認

    View full-size slide

  57. JFR をより活用する

    View full-size slide

  58. JFR でヒープ統計を有効にする

    View full-size slide

  59. ❏ 先程の例では JFR で「メモリー」に関する詳細情報は確認でき
    なかったが、 “path-to-gc-roots=true” オプションをつけて
    実行することでヒープ統計を有効にすることができる
    ❏ このオプションは記録の終了時にガベージ・コレクション(GC)のルート
    へのパスを収集するためのフラグ
    JFR でヒープ統計を有効にする
    $ java \
    -XX:StartFlightRecording=\
    dumponexit=true,\
    filename=./output/jdbc-bad-sample-FULLGC.jfr,\
    path-to-gc-roots=true \
    -Xms20M -Xmx20M -jar
    ./target/jdbc-bad-sample-FULLGC.jfr
    $ jcmd JFR.dump filename=recording.jfr
    path-to-gc-roots=true
    ※ -XX:StartFlightRecording オプションを付けて起動

    View full-size slide

  60. ❏ “path-to-gc-roots=true” を有効にすると、実行の開始
    時と終了時に Old ガベージ・コレクションがトリガーされ
    るため、通常よりもパフォーマンスの悪化が発生する
    ❏ パフォーマンスの遅延を検証する際や、パフォーマンスを
    悪化させてはいけない環境での実行は控える
    JFR でヒープ統計を有効にする際の注意点
    4 JFRを使用したパフォーマンスの問題のトラブルシューティング:
    https://docs.oracle.com/javase/jp/9/troubleshoot/troubleshoot-performance-issues-using-jfr.htm

    View full-size slide

  61. ❏ “path-to-gc-roots=true” を有効にすると、「メモリー」か
    ら「ヒープのライブ・セット傾向」「ライブ・オブジェクト
    数」が表示される
    JFR でヒープ統計を有効にする

    View full-size slide

  62. ❏ 「ヒープのライブ・セット傾向」では、メモリリー
    クが発生するオブジェクトの候補が表示される
    JFR でヒープ統計を有効にする
    1つめのリーク候補:
    “AbandonedConnectionCleanupThread$ConnectionFinalizerPha
    ntomReference.networkResources”
    が表示されている
    2つめのリーク候補: ”JVMCI” から参照されている HashMap オブ
    ジェクトが対象になっている。JVMCI は Java で JIT を作るための
    インターフェースなので、今回は関係なさそう
    (https://www.sakatakoichi.com/entry/2017/11/27/193000)

    View full-size slide

  63. ❏ 「ライブ・オブジェクト数」では、GC の対象外となるオ
    ブジェクト (OOME の原因となりそうなオブジェクト) が
    表示される
    JFR でヒープ統計を有効にする
    ライブ・オブジェクトのサンプル:
    AbandonedConnectionCleanupT
    hread というクラスに関するオブ
    ジェクトが赤文字で表示されてお
    り、OOME の原因と考えられる

    View full-size slide

  64. ❏ ヒープ統計の情報から、 AbandonedConnectionCleanupThread の
    オブジェクトが増え続けているため、このオブジェクトが OOME の原
    因ではないかという仮説も立つ
    ❏ 調べて見ると AbandonedConnectionCleanupThread は、放置され
    た MySQL DB の Connection を close してくれる Thread で、度々
    メモリリークの原因にもなっているよう
    ❏ 最初に調べたときは、この AbandonedConnectionCleanupThread
    のバグを踏んだのかとも考えた
    補足: AbandonedConnectionCleanupThread
    MySQL Connector/J (JDBC ドライバ)の罠まとめ: https://saiya-moebius.hatenablog.com/entry/2014/08/20/2304

    View full-size slide

  65. ❏ しかし JMC の「Java アプリケーション」→「スレッド」を選択し、
    mysql-cj-abandoned-connection-cleanup のスレッドを確認する
    と、特にこのスレッドは実行されていないように見える
    補足: AbandonedConnectionCleanupThread

    View full-size slide

  66. ❏ また、ヒープダンプを見た限りでは MySQL の Connection 周りのオブジェ
    クトが OOME の原因だった
    ❏ よって、AbandonedConnectionCleanupThread が直接の原因ではなく、
    Close できない Connection が原因で 、
    AbandonedConnectionCleanupThread のオブジェクトが増加しているため
    このような結果になったと考えられる
    ❏ OOME の調査をする際は、JFR だけの情報だけではなく、ヒープダンプなど
    の情報も合わせて多角的に調査する必要があるのでは
    補足: AbandonedConnectionCleanupThread
    ※ この件については自分なりに調査しましたが、推測の域を出ない部分があるので詳しい方がいらっしゃいましたらご連絡いただけますと幸いです。
    AbandonedConnectionCleanupThread の実装:
    https://github.com/LucasPln/ProjetOOSE/blob/master/lib/mysql-connector-java-5.1.48/src/com/mysql/jdbc/AbandonedConnectionCleanup
    Thread.java
    ReferenceQueue javadoc: https://docs.oracle.com/javase/jp/8/docs/api/java/lang/ref/ReferenceQueue.html

    View full-size slide

  67. JFR でより詳細な情報を取得する

    View full-size slide

  68. ❏ JFR を実行する際、デフォルトではオーバーヘッドの少な
    い “${JAVA_HOME}/lib/jfr/default.jfc” が指定されて
    実行される
    ❏ “${JAVA_HOME}/lib/jfr/profile.jfc” を指定すること
    で、より詳細な情報が取得できる。.jfc ファイルの記述を
    変更して取得情報のカスタマイズも可能。
    ❏ ただし詳細な情報を取得しようとすると、実行時のオーバー
    ヘッドは大きくなるので注意
    JFR でより詳細な情報を取得する

    View full-size slide

  69. ❏ 例えば “path-to-gc-roots” オプションは、profile.jfc
    を指定すると、リークの可能性があるオブジェクトに対し
    て、割り当てられている場所からのスタックトレースを確
    認することができる
    JFR でより詳細な情報を取得する
    java \
    -XX:StartFlightRecording=\
    dumponexit=true,\
    filename=./output/jdbc-bad-sample-FULLGC-profile.jfr,\
    disk=true,\
    path-to-gc-roots=true,\
    settings=profile \
    -Xms20M -Xmx20M -jar ./target/jdbc-bad-sample.jar
    Java Platform, Standard Edition Java Flight Recorderコマンド・リファレンス
    https://docs.oracle.com/javacomponents/jp/jmc-5-5/jfr-command-reference/diagnostic-command-reference.htm

    View full-size slide

  70. JFR でより詳細な情報を取得する
    ❏ 「ライブ・オブジェクトのサンプル」でリーク候補を選択
    すると、スタックトレースが表示されるようになる
    ライブ・オブジェクトのサンプル:
    AbandonedConnectionCleanupThread
    クラスに関するオブジェクトが赤文字で表
    示されている
    スタックトレース:
    Main Thread から
    java.sql.DriverManager.getConnection
    という記載があり、Connection 周りで参
    照されているオブジェクトにメモリリーク
    の原因がありそうと推測できる

    View full-size slide

  71. ❏ この発表では FullGC, OOME が発生するアプリケーショ
    ンに対し、原因を突き止めるために JFR, JMC, Memory
    Analyzer などのツールを用いた方法をご紹介した
    ❏ 参考文献、まとまった書籍などがなかなかない分野と感じ
    ているので、皆様も是非情報発信していただけると嬉しい
    です!
    まとめ

    View full-size slide

  72. ❏ Java Platform, Standard Editionトラブルシューティング・ガイド
    ❏ https://docs.oracle.com/javase/jp/8/docs/technotes/guides/troubles
    hoot/toc.html
    ❏ Oracle の公式ドキュメント
    ❏ 様々なツールの使い方や、役立つオプションなどの情報が豊富
    ❏ Javaパフォーマンス
    ❏ https://www.amazon.co.jp/dp/4873117186/
    ❏ Java アプリケーションを運用する上でのノウハウが詰まっている
    オススメの参考文献
    https://www.oreilly.co.jp/books/images/picture_large978-4-87311-718-8.jpeg

    View full-size slide

  73. ご清聴ありがとうございました

    View full-size slide