Lock in $30 Savings on PRO—Offer Ends Soon! ⏳

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. 自己紹介 @Takaichi00 tomoaki.takaichi.5 ・髙市 智章(タカイチ トモアキ) ・Java でのシステム開発 ・CI /

    CD ・Container / k8s ・アジャイル開発実践 共著: クリーンなコードへの SonarQube即効活用術 www.amazon.co.jp/dp/B086ML43DH
  2. ❏ 以前、検証では成功した Java のプログラムが商用で失敗するという ことを経験した ❏ PreparedStatement / ResultSet の

    close 忘れによりE (OOME) が 発生してしまうことが原因だった 本日お話すること 参考: 【JUGナイトセミナー】検証では成功した Java のパッチが商用でコケた件
  3. ❏ 前回事例を発表した LT では、プログラムに問題がありそ うな箇所をあらかた特定できていたため、GC Viewer を 用いてトライアンドエラーで問題を解決できた ❏ しかし

    Java アプリケーションを運用する上で実際に発生 する問題には、原因に見当がつかないものも多いのでは 本日お話すること
  4. ❏ 今回ではこの問題に対して「もし原因の見当すらついていな かった場合どのように対処するか?」という観点で、JFR (JDK Flight Recorder) などのツールを用いながら問題解決をしてい く流れを発表する ❏ 以下のような方を対象に、この発表が参考になれば幸い

    ❏ JFR などのツールは聞いたことがあるが使ったことがない、これから使っ てみたいので概要や使い方を知りたいという方 ❏ プログラミング言語としての Java だけではなく、JVM / GC / Heap / Stack / Thread などの技術にも触れてみたいという方 本日お話すること
  5. ❏ 以下のような 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` を取得 / 判定処理
  6. 問題の実装コードと実行コマンド TEBLE_A から SELECT したデータ を List に格納 List の数だけ

    TEBLE_B に対して SELECT を実行 TEBLE_B で取得できた結果の数だ け、再度 TEBLE_C に対して SELECT を実行 (※) 今回は再現のため、簡略的に TABLE_C ではなく TABLE_B に SELECT を実行
  7. ❏ 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 を使用
  8. ❏ JVM にはエルゴノミクスというプロセスがあり、マシンのスペックに 応じてヒープサイズが自動決定される ❏ デフォルトでは以下の設定となっている ヒープオプションを追加する 初期ヒープ・サイズ 物理メモリーの 1/64

    (最大1GB) 最大ヒープ・サイズ 物理メモリの 1/4 (最大1GB) ❏ 今回 jar を実行した商用環境では、メモリが 1GB となっていたため、 最大でも250 MB 程度しかヒープを使うことができない状態 ❏ 一時対処として jar 実行時に、-Xms512M -Xmx512M のようにヒー プサイズを設定することで、時間はかかったが処理を完了させること ができた
  9. ❏ 似たようなプログラムを実装し、ヒープサイズ 20MB と指定 し、GC ログを出力するようにして実行した結果、処理が進 むに連れ FullGC が発生して最終的に OutOfMemoryError

    が発生した (データ量約1万件) 問題のプログラムを GC Viewer を用いて解析 $ java -Xlog:gc:./gc.log \ -Xlog:gc* \ -Xms20M -Xmx20M -jar hoge.jar GC ログをファイルに出力して実行し、GC Viewer からログファイルを読み込む
  10. 問題が発生した事例のまとめ ❏ ヒープサイズは指定して実行しないと、マシンによって実 行結果に差異が出る可能性 (エルゴノミクス) ❏ DB 接続処理などで実施すべき close 処理は怠らない

    ❏ できるなら商用環境のデータ量でテストを実施する ❏ GC ログ, GC Viewer を用いてアプリケーションの内部状 態を手軽に確認できる
  11. ❏ プログラムに問題がありそうな箇所をあらかた特定できていたため、 GC Viewer を用いてトライアンドエラーで問題を解決できた ❏ しかし実際に発生する問題には、原因に見当がつかないものも多い ❏ GC log,

    GC Viewer だけでは原因追求は難しい ❏ そこで「もし原因の見当すらついていなかった場合どのように 対処するか?」という観点でこのプログラムを解析していく 問題の特定をどのようにするか
  12. ❏ アプリケーションの実行結果では「Exception in thread "main" java.lang.OutOfMemoryError: Java heap space」 というエラーメッセージが表示された

    ❏ よって今回では Heap Memory がいっぱいになったということが わかる OOME が発生した実行結果のログを確認する アプリケーションの実行結果:
  13. 補足: OOME の種類 Exception in thread "main" java.lang.OutOfMemoryError: <Message> #

    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
  14. ❏ JFR (JDK Flight Recorder) とは、OpenJDK 11 から無 償利用できるようになった、Java アプリケーションの障

    害分析ツール ❏ 現在では OpenJDK 8 update 262 にバックポートされている ❏ CPU / ヒープ / GC / Thread … など、Java アプリケー ションに関する様々なメトリクスを確認することができる JFR (JDK Flight Recorder) とは
  15. ❏ 実行時に “-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
  16. ❏ .jfr ファイルを取得するには、Java の実行オプションで 指定する以外にも、 jcmd コマンドを利用した以下のよう な方法がある 補足: JFR

    の取得方法 $ java -XX:StartFlightRecording -Xms20M -Xmx20M -jar ./target/jdbc-bad-sample-FULLGC.jar # 1分間の間 JFR の記録を実行し、ファイルに出力する $ jcmd <java pid> JFR.start duration=1m filename=recording.jfr # JFR の記録の実行中にデータをファイルに書き込み、記録の実行を継続する $ jcmd <java pid> 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
  17. ❏ 作成された .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
  18. JMC で Java アプリケーションを解析する ❏ 「Java アプリケーショ ン」ではアプリケーショ ンの全体概要を表示する ことが可能

    ❏ スレッド / CPU 使用率 / ヒープ使用率 / GC 起 因等によるユーザーコー ドの停止時間 などを確 認することができる
  19. JMC で Java アプリケーションを解析する スレッド情報: main スレッドでプ ロファイリングが実施されてい る。対象のスレッドはクリックで 選択可能

    ヒープ使用量: 徐々にヒープが上昇 し続けている 停止: 実行時間と共に、GC 起因等に よるユーザーコードの停止時間が長 くなってきている
  20. JMC で Java アプリケーションを解析する ヒープ: 時間とともに上昇を続けて おり、GC が発生しても適切にメモ リが開放されていない ❏

    「メモリー」では、マシン全体 のメモリサイズ、使用されてい るヒープ、GC の発生頻度と時 間などが確認できる ❏ ヒープ統計を有効にしていない ので、ヒープに関する詳細な統 計情報は表示されていない ガベージ・コレクション (GC): 時 間とともにに GC にかかる時間が 増加している
  21. JMC で Java アプリケーションを解析する ❏ 「メモリー」→ 「ライブ・オ ブジェクト数」から、GC の対 象外となるオブジェクト

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

    情報を取得することができる GC ID / コレクタ名: “G1Full” が 表示されており、Full GC が頻発し ている 最長の一時休止 / 一時停止合計: 実 行時間の経過に伴い、Full GC が頻 発しているためアプリケーション の休止時間も増加傾向にある
  23. ❏ 作成された .hprof ファイルは Memory Analyzer で解析す ることができる ❏ Memory

    Analyzer は Eclipse Foundation のページ (http://www.eclipse.org/mat/) からダウンロードが可能 .hprof ファイルを Memory Analyzer で解析する http://www.eclipse.org/mat/
  24. ❏ 「Actions」→「Histogram」を選択すると、Class の一 覧と Object 数、Object 単体のサイズ (Shallow Heap)、Object が持つ他の

    Object を含めたサイズ (Retained Heap) がリストで表示される .hprof ファイルを Memory Analyzer で解析する
  25. .hprof ファイルを Memory Analyzer で解析する ❏ Retained Heap の多い順にリストを並び替えると java.lang.Object,

    CopyOnWriteArrayList の下に com.mysql.cj.jdbc.~ のクラスが続いている ❏ ここから MySQL の Connection 周りで大きく heap を使ってい ることがわかる
  26. .hprof ファイルを Memory Analyzer で解析する ❏ 一番 heap を使っている java.lang.Object

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

    していく と、”com.mysql.cj.jdbc.~” の Object が大量に存在していること がわかる ❏ ”ConnectionImpl” ❏ “ClientPreparedStatement” ❏ “ResultSetImpl” ❏ よって MySQL DB へ接続する処理 で、Connection 処理が適切に close されていないのでは? とい う仮説をたてることができる
  28. ❏ 問題が発生したアプリケーションのコードの PreparedStatement, ResultSet が利用されている部分 を確認すると、確かに close 処理が記述されていない ❏ close

    処理を実施したうえで、再度解析を実施してみる OOME の原因を解消して再度解析する PreparedStatement と ResultSet の close 処理 をそれぞれ記載
  29. ❏ PreparedStatement と ResultSet の close 処理を行った アプリケーションを実行すると、問題なく処理が完了した ❏ JFR

    で解析してみると以下のように、適切にメモリが開放さ れていることがわかる OOME の原因を解消して再度解析する OOME 発生時に表示されていた赤い 「!」マークも今回は表示されていない ※ 「環境」→「プロセス」に表示されている ものはローカル PC の CPU 使用率に起因し、 マシンで実行している他のアプリケーション の影響も受けるので今回は対象外と考える
  30. ❏ OOME は発生しないので、前回とは別の方法でヒープダン プを取得する ❏ 処理の後半で jmap コマンドを実行し、ヒープダンプを取 得して Memory

    Analyzer で解析する # ヒープダンプの生成前に FullGC を実施 $ jmap -dump:live,file=<FILE_PATH> <JAVA_PID> # 以下のコマンドでも ヒープダンプを取得可能 $ jcmd <JAVA_PID> GC.heap_dump <FILE_PATH> OOME の原因を解消してヒープダンプを取得
  31. ❏ 取得できた .hprof ファイルを Memory Analyzer で開いてみると、 ヒープ全体のサイズは 6.6MB と

    20MB の上限まで余裕があり、円グ ラフで一番割合が多い部分は java.lang.Thread (main) となっている ❏ OOME 発生時に Heap の多くの割合を占めていた com.mysql.cj.jdbc.ConnectionImpl は見られない OOME の原因を解消してヒープダンプを取得 ※ 灰色の部分は Remainder とい う、上位の割合を占めないその他 の Heap を合計したもの
  32. ❏ 前回同様「Histgram」から一番 heap を使っている java.lang.Object の "Merge Shortest Path to

    GC Roots" を 開いて見てみても、”com.mysql.cj.jdbc” のオブジェクトは見 られない → OOME の問題は解消と判断できる OOME の原因を解消して ヒープダンプ を取得
  33. ここまでのまとめ ❏ JFR を有効にし、JMC を用いて解析を行うことでアプリ ケーションがどのようなヒープ、GC の傾向によって OOME エラーが発生したかを把握 ❏

    OOME 発生時にヒープダンプを取得することで、 OOME の原因となっているオブジェクトを特定 ❏ 原因と思われる箇所を修正し、再度同様の解析を実施して 問題が解消されていることを確認
  34. ❏ 先程の例では 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 <java pid> JFR.dump filename=recording.jfr path-to-gc-roots=true ※ -XX:StartFlightRecording オプションを付けて起動
  35. ❏ 「ヒープのライブ・セット傾向」では、メモリリー クが発生するオブジェクトの候補が表示される JFR でヒープ統計を有効にする 1つめのリーク候補: “AbandonedConnectionCleanupThread$ConnectionFinalizerPha ntomReference.networkResources” が表示されている 2つめのリーク候補:

    ”JVMCI” から参照されている HashMap オブ ジェクトが対象になっている。JVMCI は Java で JIT を作るための インターフェースなので、今回は関係なさそう (https://www.sakatakoichi.com/entry/2017/11/27/193000)
  36. ❏ 「ライブ・オブジェクト数」では、GC の対象外となるオ ブジェクト (OOME の原因となりそうなオブジェクト) が 表示される JFR でヒープ統計を有効にする

    ライブ・オブジェクトのサンプル: AbandonedConnectionCleanupT hread というクラスに関するオブ ジェクトが赤文字で表示されてお り、OOME の原因と考えられる
  37. ❏ ヒープ統計の情報から、 AbandonedConnectionCleanupThread の オブジェクトが増え続けているため、このオブジェクトが OOME の原 因ではないかという仮説も立つ ❏ 調べて見ると

    AbandonedConnectionCleanupThread は、放置され た MySQL DB の Connection を close してくれる Thread で、度々 メモリリークの原因にもなっているよう ❏ 最初に調べたときは、この AbandonedConnectionCleanupThread のバグを踏んだのかとも考えた 補足: AbandonedConnectionCleanupThread MySQL Connector/J (JDBC ドライバ)の罠まとめ: https://saiya-moebius.hatenablog.com/entry/2014/08/20/2304
  38. ❏ また、ヒープダンプを見た限りでは 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
  39. ❏ JFR を実行する際、デフォルトではオーバーヘッドの少な い “${JAVA_HOME}/lib/jfr/default.jfc” が指定されて 実行される ❏ “${JAVA_HOME}/lib/jfr/profile.jfc” を指定すること

    で、より詳細な情報が取得できる。.jfc ファイルの記述を 変更して取得情報のカスタマイズも可能。 ❏ ただし詳細な情報を取得しようとすると、実行時のオーバー ヘッドは大きくなるので注意 JFR でより詳細な情報を取得する
  40. ❏ 例えば “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
  41. ❏ この発表では FullGC, OOME が発生するアプリケーショ ンに対し、原因を突き止めるために JFR, JMC, Memory Analyzer

    などのツールを用いた方法をご紹介した ❏ 参考文献、まとまった書籍などがなかなかない分野と感じ ているので、皆様も是非情報発信していただけると嬉しい です! まとめ
  42. ❏ 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