Upgrade to Pro
— share decks privately, control downloads, hide ads and more …
Speaker Deck
Features
Speaker Deck
PRO
Sign in
Sign up for free
Search
Search
JJUG CCC 2021 Spring-Resolving OOME with JFR
Search
Takaichi00
May 07, 2021
Technology
2
3k
JJUG CCC 2021 Spring-Resolving OOME with JFR
JJUG CCC 2021 Spring の「JFR などのツールを用いて FullGC や OOME の原因を特定する流れ」の登壇資料です。
Takaichi00
May 07, 2021
Tweet
Share
More Decks by Takaichi00
See All by Takaichi00
自分から始めるアジャイルの道 ~内発的動機をきっかけに変わった価値観~
takaichi00
0
120
Java developer introduced to Rust-ADC2022
takaichi00
0
220
野球人・落合博満さんから学ぶ、アジャイルなマインドセット・プラクティス
takaichi00
1
760
【CICD2021】デプロイメントパイプラインの原理原則を再確認する / Confirm Deployment Pipeline Principle
takaichi00
11
4.3k
【JTF2021】SonarQube をより有効活用する / Effective SonarQube
takaichi00
0
2.3k
【Yahoo! JAPAN Agile 2nd】野球人・落合博満さんから学ぶスクラムマスター / デベロッパー
takaichi00
0
2.6k
【Developers Boost 2020】凡人エンジニアの生存戦略
takaichi00
1
2.6k
【ソフトウェアテスト自動化カンファレンス2020】CI パイプラインでのテスト戦略とその実現方法
takaichi00
3
5.2k
【JJUG CCC 2020 Fall】Selenide + Cucumber で実現する UI テスト自動化 + BDD
takaichi00
0
1.6k
Other Decks in Technology
See All in Technology
リンクアンドモチベーション ソフトウェアエンジニア向け紹介資料 / Introduction to Link and Motivation for Software Engineers
lmi
4
300k
Evangelismo técnico: ¿qué, cómo y por qué?
trishagee
0
360
[CV勉強会@関東 ECCV2024 読み会] オンラインマッピング x トラッキング MapTracker: Tracking with Strided Memory Fusion for Consistent Vector HD Mapping (Chen+, ECCV24)
abemii
0
220
障害対応指揮の意思決定と情報共有における価値観 / Waroom Meetup #2
arthur1
5
470
Security-JAWS【第35回】勉強会クラウドにおけるマルウェアやコンテンツ改ざんへの対策
4su_para
0
170
Amplify Gen2 Deep Dive / バックエンドの型をいかにしてフロントエンドへ伝えるか #TSKaigi #TSKaigiKansai #AWSAmplifyJP
tacck
PRO
0
370
DMARC 対応の話 - MIXI CTO オフィスアワー #04
bbqallstars
1
160
Oracle Cloud Infrastructureデータベース・クラウド:各バージョンのサポート期間
oracle4engineer
PRO
28
12k
10XにおけるData Contractの導入について: Data Contract事例共有会
10xinc
5
600
安心してください、日本語使えますよ―Ubuntu日本語Remix提供休止に寄せて― 2024-11-17
nobutomurata
1
990
サイバーセキュリティと認知バイアス:対策の隙を埋める心理学的アプローチ
shumei_ito
0
380
The Role of Developer Relations in AI Product Success.
giftojabu1
0
120
Featured
See All Featured
10 Git Anti Patterns You Should be Aware of
lemiorhan
654
59k
XXLCSS - How to scale CSS and keep your sanity
sugarenia
246
1.3M
Exploring the Power of Turbo Streams & Action Cable | RailsConf2023
kevinliebholz
27
4.3k
RailsConf & Balkan Ruby 2019: The Past, Present, and Future of Rails at GitHub
eileencodes
131
33k
Statistics for Hackers
jakevdp
796
220k
CSS Pre-Processors: Stylus, Less & Sass
bermonpainter
356
29k
Performance Is Good for Brains [We Love Speed 2024]
tammyeverts
6
410
Raft: Consensus for Rubyists
vanstee
136
6.6k
ピンチをチャンスに:未来をつくるプロダクトロードマップ #pmconf2020
aki_iinuma
109
49k
A Modern Web Designer's Workflow
chriscoyier
693
190k
Put a Button on it: Removing Barriers to Going Fast.
kastner
59
3.5k
Refactoring Trust on Your Teams (GOTO; Chicago 2020)
rmw
31
2.7k
Transcript
JFR などのツールを用いて FullGC や OOME の原因を特定する流れ # jjug #jjug_ccc 髙市
智章 (Tomoaki Takaichi) May, 23, 2021 JJUG CCC 2021 Spring
自己紹介 @Takaichi00 tomoaki.takaichi.5 ・髙市 智章(タカイチ トモアキ) ・Java でのシステム開発 ・CI /
CD ・Container / k8s ・アジャイル開発実践 共著: クリーンなコードへの SonarQube即効活用術 www.amazon.co.jp/dp/B086ML43DH
❏ 以前、検証では成功した Java のプログラムが商用で失敗するという ことを経験した ❏ PreparedStatement / ResultSet の
close 忘れによりE (OOME) が 発生してしまうことが原因だった 本日お話すること 参考: 【JUGナイトセミナー】検証では成功した Java のパッチが商用でコケた件
❏ 前回事例を発表した LT では、プログラムに問題がありそ うな箇所をあらかた特定できていたため、GC Viewer を 用いてトライアンドエラーで問題を解決できた ❏ しかし
Java アプリケーションを運用する上で実際に発生 する問題には、原因に見当がつかないものも多いのでは 本日お話すること
❏ 今回ではこの問題に対して「もし原因の見当すらついていな かった場合どのように対処するか?」という観点で、JFR (JDK Flight Recorder) などのツールを用いながら問題解決をしてい く流れを発表する ❏ 以下のような方を対象に、この発表が参考になれば幸い
❏ JFR などのツールは聞いたことがあるが使ったことがない、これから使っ てみたいので概要や使い方を知りたいという方 ❏ プログラミング言語としての Java だけではなく、JVM / GC / Heap / Stack / Thread などの技術にも触れてみたいという方 本日お話すること
❏ 発表内容には誤りが無いよう、様々な文献などを参考にし て最善を尽くしておりますが、まだまだ知識が足りないと 感じています ❏ もし発表内容に誤りがある / もっと効率的な調査方法や ツールがあるといった場合には、その旨をご連絡・ご発信 いただけますと幸いです
発表内容にあたって https://www.oreilly.co.jp/books/images/picture_large978-4-87311-718-8.jpeg
問題が発生した事例の紹介
❏ 今回のサンプルアプリケーションは Github にて公開中 ❏ Java と Docker の環境があれば再現が可能 問題が発生したアプリケーションのサンプル
Takaichi00 / jfr-sample: https://github.com/Takaichi00/jfr-sample
❏ 以下のような 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` を取得 / 判定処理
問題の実装コードと実行コマンド TEBLE_A から SELECT したデータ を List に格納 List の数だけ
TEBLE_B に対して SELECT を実行 TEBLE_B で取得できた結果の数だ け、再度 TEBLE_C に対して SELECT を実行 (※) 今回は再現のため、簡略的に TABLE_C ではなく TABLE_B に SELECT を実行
❏ ローカル PC (メモリ 16GB) から、検証用のデータが入っ た検証用 DB へ向けてこのパッチを起動したところ、問題 なく実行が完了した
(データ量は数十件程度) 検証の構成では成功 検証環境 成功 メモリ: 16GB
❏ 商用環境では VM 上 (メモリ 1GB) で作成したパッチを実 行した。しかし処理が全然完了しなかった ❏ 商用のデータ量は検証環境よりは多いが、たかだか1万件
未満程度のもの 商用環境では失敗 商用環境 失敗 メモリ: 1GB
❏ 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 を使用
❏ JVM にはエルゴノミクスというプロセスがあり、マシンのスペックに 応じてヒープサイズが自動決定される ❏ デフォルトでは以下の設定となっている ヒープオプションを追加する 初期ヒープ・サイズ 物理メモリーの 1/64
(最大1GB) 最大ヒープ・サイズ 物理メモリの 1/4 (最大1GB) ❏ 今回 jar を実行した商用環境では、メモリが 1GB となっていたため、 最大でも250 MB 程度しかヒープを使うことができない状態 ❏ 一時対処として jar 実行時に、-Xms512M -Xmx512M のようにヒー プサイズを設定することで、時間はかかったが処理を完了させること ができた
❏ 後日コードレビューにより、PreparedStatement / ResultSet の close 忘れが発覚 ❏ 本当にこれらが原因なのか検証するため、まずは GC
Viewer を用いて簡易的に解析 そもそも実装コードが悪い
❏ GC ログから、GC の発生やそれに伴うヒープの推移など が視覚的に表示できるツール ❏ もともと tagtraum 社によって開発されていたが、2008 年で開発がストップされており、現在は個人の方が開発を
続けているツール GC Viewer とは GC Viewer のダウンロード: https://github.com/chewiebug/GCViewer/wiki/Changelog
❏ 似たようなプログラムを実装し、ヒープサイズ 20MB と指定 し、GC ログを出力するようにして実行した結果、処理が進 むに連れ FullGC が発生して最終的に OutOfMemoryError
が発生した (データ量約1万件) 問題のプログラムを GC Viewer を用いて解析 $ java -Xlog:gc:./gc.log \ -Xlog:gc* \ -Xms20M -Xmx20M -jar hoge.jar GC ログをファイルに出力して実行し、GC Viewer からログファイルを読み込む
❏ PreparedStatement / ResultSet を close するよう処理 を修正したところ FullGC は発生せず適切にメモリが開放
されて処理が継続できた (データ量約1万件) 解決方法
問題が発生した事例のまとめ ❏ ヒープサイズは指定して実行しないと、マシンによって実 行結果に差異が出る可能性 (エルゴノミクス) ❏ DB 接続処理などで実施すべき close 処理は怠らない
❏ できるなら商用環境のデータ量でテストを実施する ❏ GC ログ, GC Viewer を用いてアプリケーションの内部状 態を手軽に確認できる
もし問題点がわからなかったら どのように対処するか?
❏ プログラムに問題がありそうな箇所をあらかた特定できていたため、 GC Viewer を用いてトライアンドエラーで問題を解決できた ❏ しかし実際に発生する問題には、原因に見当がつかないものも多い ❏ GC log,
GC Viewer だけでは原因追求は難しい ❏ そこで「もし原因の見当すらついていなかった場合どのように 対処するか?」という観点でこのプログラムを解析していく 問題の特定をどのようにするか
OutOfMemoryError のメッ セージを確認する
❏ アプリケーションの実行結果では「Exception in thread "main" java.lang.OutOfMemoryError: Java heap space」 というエラーメッセージが表示された
❏ よって今回では Heap Memory がいっぱいになったということが わかる OOME が発生した実行結果のログを確認する アプリケーションの実行結果:
❏ しかしこの情報だけでは、単に使用中のオブジェクトが多すぎ てヒープに収まらなくなったのか、不使用になったオブジェク トを開放せず、新しいオブジェクトの割当を続けていることが 原因なのかがわからない ❏ 単にヒープサイズを拡大したら問題なく動いた、というのは 本質的な解決策ではない OOME が発生した実行結果のログを確認する
補足: 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
JFR (JDK Flight Recorder) での解析
❏ JFR (JDK Flight Recorder) とは、OpenJDK 11 から無 償利用できるようになった、Java アプリケーションの障
害分析ツール ❏ 現在では OpenJDK 8 update 262 にバックポートされている ❏ CPU / ヒープ / GC / Thread … など、Java アプリケー ションに関する様々なメトリクスを確認することができる JFR (JDK Flight Recorder) とは
❏ 実行時に “-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
❏ .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
❏ 作成された .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
❏ JMC を起動し、「ファイル(F)」→「ファイルを開く」か ら、生成した jdbc-bad-sample-FULLGC.jfr を選択する と、分析結果が表示されていることを確認できる FullGC が発生するアプリケーションを JFR
/ JMC で で解析
JMC で Java アプリケーションを解析する ❏ 問題なありそうな箇所は、赤い 「!」アイコン で表示されている ❏ まずは左メニューから「アウトラ
イン」→「Java アプリケーショ ン」を選択し、アプリケーション の解析結果を確認する
JMC で Java アプリケーションを解析する ❏ 「Java アプリケーショ ン」ではアプリケーショ ンの全体概要を表示する ことが可能
❏ スレッド / CPU 使用率 / ヒープ使用率 / GC 起 因等によるユーザーコー ドの停止時間 などを確 認することができる
JMC で Java アプリケーションを解析する スレッド情報: main スレッドでプ ロファイリングが実施されてい る。対象のスレッドはクリックで 選択可能
ヒープ使用量: 徐々にヒープが上昇 し続けている 停止: 実行時間と共に、GC 起因等に よるユーザーコードの停止時間が長 くなってきている
JMC で Java アプリケーションを解析する ヒープ: 時間とともに上昇を続けて おり、GC が発生しても適切にメモ リが開放されていない ❏
「メモリー」では、マシン全体 のメモリサイズ、使用されてい るヒープ、GC の発生頻度と時 間などが確認できる ❏ ヒープ統計を有効にしていない ので、ヒープに関する詳細な統 計情報は表示されていない ガベージ・コレクション (GC): 時 間とともにに GC にかかる時間が 増加している
JMC で Java アプリケーションを解析する ❏ 「メモリー」→ 「ライブ・オ ブジェクト数」から、GC の対 象外となるオブジェクト
(OOME の原因となりそうなオ ブジェクト) を確認することが できる ❏ しかしヒープ統計を有効にし ていないので、詳細な統計情 報は表示されていない ライブオブジェクトとは... ガベージコレクタの仕組みを理解する: https://www.atmarkit.co.jp/ait/articles/0404/02/news079.html
JMC で Java アプリケーションを解析する ❏ 「JVM 内部」→ 「ガベージコ レクション」から、GC の統計
情報を取得することができる GC ID / コレクタ名: “G1Full” が 表示されており、Full GC が頻発し ている 最長の一時休止 / 一時停止合計: 実 行時間の経過に伴い、Full GC が頻 発しているためアプリケーション の休止時間も増加傾向にある
ここまでのまとめ ❏ アプリケーションの実行時間が進むにつれ... ❏ FullGC が徐々に発生し始め、頻度が高くなる ❏ ヒープ使用率が徐々に増加している ❏ アプリケーションの休止時間が多くなる
❏ しかし原因の特定までは至っていない
❏ JFR / JMC を用いた解析で、徐々にヒープ使用率が上昇し ていることがわかる ❏ 単にヒープサイズが足りないのが原因ではなさそう。 ヒープを増やしても問題の本質的な解決になならない ❏
使用されているヒープのうち、何がヒープ上昇の原因と なっているかを追求する Next Action
ヒープダンプを取得し Memory Analyzer で解析
❏ ヒープダンプを取得することで、ヒープの内訳を確認する ❏ ヒープダンプの取得方法は複数あるが、まずは OOME 発 生時にヒープダンプを生成してくれる “-XX:+HeapDumpOnOutOfMemoryError” をつけて実 行してみる
ヒープダンプ を取得する $ java \ -XX:+HeapDumpOnOutOfMemoryError \ -XX:HeapDumpPath=./output \ -Xms20M -Xmx20M -jar ./target/jdbc-bad-sample.jar
❏ 作成された .hprof ファイルは Memory Analyzer で解析す ることができる ❏ Memory
Analyzer は Eclipse Foundation のページ (http://www.eclipse.org/mat/) からダウンロードが可能 .hprof ファイルを Memory Analyzer で解析する http://www.eclipse.org/mat/
❏ 「File」→「Open File」から、先程作成された .hprof ファ イルを開くと、以下のように解析された画面が表示される ❏ 円グラフの部分をクリックすると、どのオブジェクトがどの くらいの割合を占めているかを確認することができる .hprof
ファイルを Memory Analyzer で解析する
❏ このヒープダンプが取られているのは OOME 発生時なので、一番割合 を占めているものが怪しい ❏ 一番割合が多い部分をクリックすると、 com.mysql.cj.jdbc.ConnectionImpl との記載がある。よって mysql
の接続処理に問題がありそうという目星をつけることができる。 .hprof ファイルを Memory Analyzer で解析する
❏ 「Actions」→「Histogram」を選択すると、Class の一 覧と Object 数、Object 単体のサイズ (Shallow Heap)、Object が持つ他の
Object を含めたサイズ (Retained Heap) がリストで表示される .hprof ファイルを Memory Analyzer で解析する
.hprof ファイルを Memory Analyzer で解析する ❏ Retained Heap の多い順にリストを並び替えると java.lang.Object,
CopyOnWriteArrayList の下に com.mysql.cj.jdbc.~ のクラスが続いている ❏ ここから MySQL の Connection 周りで大きく heap を使ってい ることがわかる
.hprof ファイルを Memory Analyzer で解析する ❏ 一番 heap を使っている java.lang.Object
の "Merge Shortest Path to GC Roots" を開くと、生存している (GC の対象外となった) Object と、その Object が参照 している Object 群を階層構造で表示できる
.hprof ファイルを Memory Analyzer で解析する ❏ Main Thread を expand
していく と、”com.mysql.cj.jdbc.~” の Object が大量に存在していること がわかる ❏ ”ConnectionImpl” ❏ “ClientPreparedStatement” ❏ “ResultSetImpl” ❏ よって MySQL DB へ接続する処理 で、Connection 処理が適切に close されていないのでは? とい う仮説をたてることができる
仮説で浮かび上がった問題を解 消し、再度解析を実行する
❏ 問題が発生したアプリケーションのコードの PreparedStatement, ResultSet が利用されている部分 を確認すると、確かに close 処理が記述されていない ❏ close
処理を実施したうえで、再度解析を実施してみる OOME の原因を解消して再度解析する PreparedStatement と ResultSet の close 処理 をそれぞれ記載
❏ PreparedStatement と ResultSet の close 処理を行った アプリケーションを実行すると、問題なく処理が完了した ❏ JFR
で解析してみると以下のように、適切にメモリが開放さ れていることがわかる OOME の原因を解消して再度解析する OOME 発生時に表示されていた赤い 「!」マークも今回は表示されていない ※ 「環境」→「プロセス」に表示されている ものはローカル PC の CPU 使用率に起因し、 マシンで実行している他のアプリケーション の影響も受けるので今回は対象外と考える
❏ 「ガベージ・コレクション」を確認しても、FullGC は発 生しておらず、休止期間も低下していることがわかる OOME の原因を解消して再度解析する
❏ OOME は発生しないので、前回とは別の方法でヒープダン プを取得する ❏ 処理の後半で jmap コマンドを実行し、ヒープダンプを取 得して Memory
Analyzer で解析する # ヒープダンプの生成前に FullGC を実施 $ jmap -dump:live,file=<FILE_PATH> <JAVA_PID> # 以下のコマンドでも ヒープダンプを取得可能 $ jcmd <JAVA_PID> GC.heap_dump <FILE_PATH> OOME の原因を解消してヒープダンプを取得
❏ 取得できた .hprof ファイルを Memory Analyzer で開いてみると、 ヒープ全体のサイズは 6.6MB と
20MB の上限まで余裕があり、円グ ラフで一番割合が多い部分は java.lang.Thread (main) となっている ❏ OOME 発生時に Heap の多くの割合を占めていた com.mysql.cj.jdbc.ConnectionImpl は見られない OOME の原因を解消してヒープダンプを取得 ※ 灰色の部分は Remainder とい う、上位の割合を占めないその他 の Heap を合計したもの
❏ 前回同様「Histgram」から一番 heap を使っている java.lang.Object の "Merge Shortest Path to
GC Roots" を 開いて見てみても、”com.mysql.cj.jdbc” のオブジェクトは見 られない → OOME の問題は解消と判断できる OOME の原因を解消して ヒープダンプ を取得
ここまでのまとめ ❏ JFR を有効にし、JMC を用いて解析を行うことでアプリ ケーションがどのようなヒープ、GC の傾向によって OOME エラーが発生したかを把握 ❏
OOME 発生時にヒープダンプを取得することで、 OOME の原因となっているオブジェクトを特定 ❏ 原因と思われる箇所を修正し、再度同様の解析を実施して 問題が解消されていることを確認
JFR をより活用する
JFR でヒープ統計を有効にする
❏ 先程の例では 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 オプションを付けて起動
❏ “path-to-gc-roots=true” を有効にすると、実行の開始 時と終了時に Old ガベージ・コレクションがトリガーされ るため、通常よりもパフォーマンスの悪化が発生する ❏ パフォーマンスの遅延を検証する際や、パフォーマンスを 悪化させてはいけない環境での実行は控える
JFR でヒープ統計を有効にする際の注意点 4 JFRを使用したパフォーマンスの問題のトラブルシューティング: https://docs.oracle.com/javase/jp/9/troubleshoot/troubleshoot-performance-issues-using-jfr.htm
❏ “path-to-gc-roots=true” を有効にすると、「メモリー」か ら「ヒープのライブ・セット傾向」「ライブ・オブジェクト 数」が表示される JFR でヒープ統計を有効にする
❏ 「ヒープのライブ・セット傾向」では、メモリリー クが発生するオブジェクトの候補が表示される JFR でヒープ統計を有効にする 1つめのリーク候補: “AbandonedConnectionCleanupThread$ConnectionFinalizerPha ntomReference.networkResources” が表示されている 2つめのリーク候補:
”JVMCI” から参照されている HashMap オブ ジェクトが対象になっている。JVMCI は Java で JIT を作るための インターフェースなので、今回は関係なさそう (https://www.sakatakoichi.com/entry/2017/11/27/193000)
❏ 「ライブ・オブジェクト数」では、GC の対象外となるオ ブジェクト (OOME の原因となりそうなオブジェクト) が 表示される JFR でヒープ統計を有効にする
ライブ・オブジェクトのサンプル: AbandonedConnectionCleanupT hread というクラスに関するオブ ジェクトが赤文字で表示されてお り、OOME の原因と考えられる
❏ ヒープ統計の情報から、 AbandonedConnectionCleanupThread の オブジェクトが増え続けているため、このオブジェクトが OOME の原 因ではないかという仮説も立つ ❏ 調べて見ると
AbandonedConnectionCleanupThread は、放置され た MySQL DB の Connection を close してくれる Thread で、度々 メモリリークの原因にもなっているよう ❏ 最初に調べたときは、この AbandonedConnectionCleanupThread のバグを踏んだのかとも考えた 補足: AbandonedConnectionCleanupThread MySQL Connector/J (JDBC ドライバ)の罠まとめ: https://saiya-moebius.hatenablog.com/entry/2014/08/20/2304
❏ しかし JMC の「Java アプリケーション」→「スレッド」を選択し、 mysql-cj-abandoned-connection-cleanup のスレッドを確認する と、特にこのスレッドは実行されていないように見える 補足: AbandonedConnectionCleanupThread
❏ また、ヒープダンプを見た限りでは 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
JFR でより詳細な情報を取得する
❏ JFR を実行する際、デフォルトではオーバーヘッドの少な い “${JAVA_HOME}/lib/jfr/default.jfc” が指定されて 実行される ❏ “${JAVA_HOME}/lib/jfr/profile.jfc” を指定すること
で、より詳細な情報が取得できる。.jfc ファイルの記述を 変更して取得情報のカスタマイズも可能。 ❏ ただし詳細な情報を取得しようとすると、実行時のオーバー ヘッドは大きくなるので注意 JFR でより詳細な情報を取得する
❏ 例えば “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
JFR でより詳細な情報を取得する ❏ 「ライブ・オブジェクトのサンプル」でリーク候補を選択 すると、スタックトレースが表示されるようになる ライブ・オブジェクトのサンプル: AbandonedConnectionCleanupThread クラスに関するオブジェクトが赤文字で表 示されている スタックトレース:
Main Thread から java.sql.DriverManager.getConnection という記載があり、Connection 周りで参 照されているオブジェクトにメモリリーク の原因がありそうと推測できる
まとめ
❏ この発表では FullGC, OOME が発生するアプリケーショ ンに対し、原因を突き止めるために JFR, JMC, Memory Analyzer
などのツールを用いた方法をご紹介した ❏ 参考文献、まとまった書籍などがなかなかない分野と感じ ているので、皆様も是非情報発信していただけると嬉しい です! まとめ
❏ 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
ご清聴ありがとうございました