Slide 1
Slide 1 text
JFR などのツールを用いて FullGC や OOME の原因を特定する流れ
# jjug #jjug_ccc
髙市 智章 (Tomoaki Takaichi)
May, 23, 2021 JJUG CCC 2021 Spring
Slide 2
Slide 2 text
自己紹介
@Takaichi00
tomoaki.takaichi.5
・髙市 智章（タカイチ トモアキ）
・Java でのシステム開発
・CI / CD
・Container / k8s
・アジャイル開発実践
共著: クリーンなコードへの
SonarQube即効活用術
www.amazon.co.jp/dp/B086ML43DH
Slide 3
Slide 3 text
❏ 以前、検証では成功した Java のプログラムが商用で失敗するという
ことを経験した
❏ PreparedStatement / ResultSet の close 忘れによりE (OOME) が
発生してしまうことが原因だった
本日お話すること
参考: 【JUGナイトセミナー】検証では成功した Java のパッチが商用でコケた件
Slide 4
Slide 4 text
❏ 前回事例を発表した LT では、プログラムに問題がありそ
うな箇所をあらかた特定できていたため、GC Viewer を
用いてトライアンドエラーで問題を解決できた
❏ しかし Java アプリケーションを運用する上で実際に発生
する問題には、原因に見当がつかないものも多いのでは
本日お話すること
Slide 5
Slide 5 text
❏ 今回ではこの問題に対して「もし原因の見当すらついていな
かった場合どのように対処するか?」という観点で、JFR (JDK
Flight Recorder) などのツールを用いながら問題解決をしてい
く流れを発表する
❏ 以下のような方を対象に、この発表が参考になれば幸い
❏ JFR などのツールは聞いたことがあるが使ったことがない、これから使っ
てみたいので概要や使い方を知りたいという方
❏ プログラミング言語としての Java だけではなく、JVM / GC / Heap /
Stack / Thread などの技術にも触れてみたいという方
本日お話すること
Slide 6
Slide 6 text
❏ 発表内容には誤りが無いよう、様々な文献などを参考にし
て最善を尽くしておりますが、まだまだ知識が足りないと
感じています
❏ もし発表内容に誤りがある / もっと効率的な調査方法や
ツールがあるといった場合には、その旨をご連絡・ご発信
いただけますと幸いです
発表内容にあたって
https://www.oreilly.co.jp/books/images/picture_large978-4-87311-718-8.jpeg
Slide 7
Slide 7 text
問題が発生した事例の紹介
Slide 8
Slide 8 text
❏ 今回のサンプルアプリケーションは Github にて公開中
❏ Java と Docker の環境があれば再現が可能
問題が発生したアプリケーションのサンプル
Takaichi00 / jfr-sample: https://github.com/Takaichi00/jfr-sample
Slide 9
Slide 9 text
❏ 以下のような 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` を取得 / 判定処理
Slide 10
Slide 10 text
問題の実装コードと実行コマンド
TEBLE_A から SELECT したデータ
を List に格納
List の数だけ TEBLE_B に対して
SELECT を実行
TEBLE_B で取得できた結果の数だ
け、再度 TEBLE_C に対して
SELECT を実行
(※) 今回は再現のため、簡略的に
TABLE_C ではなく TABLE_B に
SELECT を実行
Slide 11
Slide 11 text
❏ ローカル PC (メモリ 16GB) から、検証用のデータが入っ
た検証用 DB へ向けてこのパッチを起動したところ、問題
なく実行が完了した (データ量は数十件程度)
検証の構成では成功
検証環境
成功
メモリ: 16GB
Slide 12
Slide 12 text
❏ 商用環境では VM 上 (メモリ 1GB) で作成したパッチを実
行した。しかし処理が全然完了しなかった
❏ 商用のデータ量は検証環境よりは多いが、たかだか1万件
未満程度のもの
商用環境では失敗
商用環境
失敗
メモリ: 1GB
Slide 13
Slide 13 text
❏ 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 を使用
Slide 14
Slide 14 text
❏ JVM にはエルゴノミクスというプロセスがあり、マシンのスペックに
応じてヒープサイズが自動決定される
❏ デフォルトでは以下の設定となっている
ヒープオプションを追加する
初期ヒープ・サイズ 物理メモリーの 1/64 (最大1GB)
最大ヒープ・サイズ 物理メモリの 1/4 (最大1GB)
❏ 今回 jar を実行した商用環境では、メモリが 1GB となっていたため、
最大でも250 MB 程度しかヒープを使うことができない状態
❏ 一時対処として jar 実行時に、-Xms512M -Xmx512M のようにヒー
プサイズを設定することで、時間はかかったが処理を完了させること
ができた
Slide 15
Slide 15 text
❏ 後日コードレビューにより、PreparedStatement /
ResultSet の close 忘れが発覚
❏ 本当にこれらが原因なのか検証するため、まずは GC
Viewer を用いて簡易的に解析
そもそも実装コードが悪い
Slide 16
Slide 16 text
❏ GC ログから、GC の発生やそれに伴うヒープの推移など
が視覚的に表示できるツール
❏ もともと tagtraum 社によって開発されていたが、2008
年で開発がストップされており、現在は個人の方が開発を
続けているツール
GC Viewer とは
GC Viewer のダウンロード:
https://github.com/chewiebug/GCViewer/wiki/Changelog
Slide 17
Slide 17 text
❏ 似たようなプログラムを実装し、ヒープサイズ 20MB と指定
し、GC ログを出力するようにして実行した結果、処理が進
むに連れ FullGC が発生して最終的に OutOfMemoryError
が発生した (データ量約1万件)
問題のプログラムを GC Viewer を用いて解析
$ java -Xlog:gc:./gc.log \
-Xlog:gc* \
-Xms20M -Xmx20M -jar hoge.jar
GC ログをファイルに出力して実行し、GC
Viewer からログファイルを読み込む
Slide 18
Slide 18 text
❏ PreparedStatement / ResultSet を close するよう処理
を修正したところ FullGC は発生せず適切にメモリが開放
されて処理が継続できた (データ量約1万件)
解決方法
Slide 19
Slide 19 text
問題が発生した事例のまとめ
❏ ヒープサイズは指定して実行しないと、マシンによって実
行結果に差異が出る可能性 (エルゴノミクス)
❏ DB 接続処理などで実施すべき close 処理は怠らない
❏ できるなら商用環境のデータ量でテストを実施する
❏ GC ログ, GC Viewer を用いてアプリケーションの内部状
態を手軽に確認できる
Slide 20
Slide 20 text
もし問題点がわからなかったら
どのように対処するか?
Slide 21
Slide 21 text
❏ プログラムに問題がありそうな箇所をあらかた特定できていたため、
GC Viewer を用いてトライアンドエラーで問題を解決できた
❏ しかし実際に発生する問題には、原因に見当がつかないものも多い
❏ GC log, GC Viewer だけでは原因追求は難しい
❏ そこで「もし原因の見当すらついていなかった場合どのように
対処するか?」という観点でこのプログラムを解析していく
問題の特定をどのようにするか
Slide 22
Slide 22 text
OutOfMemoryError のメッ
セージを確認する
Slide 23
Slide 23 text
❏ アプリケーションの実行結果では「Exception in thread
"main" java.lang.OutOfMemoryError: Java heap space」
というエラーメッセージが表示された
❏ よって今回では Heap Memory がいっぱいになったということが
わかる
OOME が発生した実行結果のログを確認する
アプリケーションの実行結果:
Slide 24
Slide 24 text
❏ しかしこの情報だけでは、単に使用中のオブジェクトが多すぎ
てヒープに収まらなくなったのか、不使用になったオブジェク
トを開放せず、新しいオブジェクトの割当を続けていることが
原因なのかがわからない
❏ 単にヒープサイズを拡大したら問題なく動いた、というのは
本質的な解決策ではない
OOME が発生した実行結果のログを確認する
Slide 25
Slide 25 text
補足: 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
Slide 26
Slide 26 text
JFR (JDK Flight Recorder)
での解析
Slide 27
Slide 27 text
❏ JFR (JDK Flight Recorder) とは、OpenJDK 11 から無
償利用できるようになった、Java アプリケーションの障
害分析ツール
❏ 現在では OpenJDK 8 update 262 にバックポートされている
❏ CPU / ヒープ / GC / Thread … など、Java アプリケー
ションに関する様々なメトリクスを確認することができる
JFR (JDK Flight Recorder) とは
Slide 28
Slide 28 text
❏ 実行時に “-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
Slide 29
Slide 29 text
❏ .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
Slide 30
Slide 30 text
❏ 作成された .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
Slide 31
Slide 31 text
❏ JMC を起動し、「ファイル(F)」→「ファイルを開く」か
ら、生成した jdbc-bad-sample-FULLGC.jfr を選択する
と、分析結果が表示されていることを確認できる
FullGC が発生するアプリケーションを JFR / JMC で で解析
Slide 32
Slide 32 text
JMC で Java アプリケーションを解析する
❏ 問題なありそうな箇所は、赤い
「！」アイコン で表示されている
❏ まずは左メニューから「アウトラ
イン」→「Java アプリケーショ
ン」を選択し、アプリケーション
の解析結果を確認する
Slide 33
Slide 33 text
JMC で Java アプリケーションを解析する
❏ 「Java アプリケーショ
ン」ではアプリケーショ
ンの全体概要を表示する
ことが可能
❏ スレッド / CPU 使用率
/ ヒープ使用率 / GC 起
因等によるユーザーコー
ドの停止時間 などを確
認することができる
Slide 34
Slide 34 text
JMC で Java アプリケーションを解析する
スレッド情報: main スレッドでプ
ロファイリングが実施されてい
る。対象のスレッドはクリックで
選択可能
ヒープ使用量: 徐々にヒープが上昇
し続けている
停止: 実行時間と共に、GC 起因等に
よるユーザーコードの停止時間が長
くなってきている
Slide 35
Slide 35 text
JMC で Java アプリケーションを解析する
ヒープ: 時間とともに上昇を続けて
おり、GC が発生しても適切にメモ
リが開放されていない
❏ 「メモリー」では、マシン全体
のメモリサイズ、使用されてい
るヒープ、GC の発生頻度と時
間などが確認できる
❏ ヒープ統計を有効にしていない
ので、ヒープに関する詳細な統
計情報は表示されていない
ガベージ・コレクション (GC): 時
間とともにに GC にかかる時間が
増加している
Slide 36
Slide 36 text
JMC で Java アプリケーションを解析する
❏ 「メモリー」→ 「ライブ・オ
ブジェクト数」から、GC の対
象外となるオブジェクト
(OOME の原因となりそうなオ
ブジェクト) を確認することが
できる
❏ しかしヒープ統計を有効にし
ていないので、詳細な統計情
報は表示されていない
ライブオブジェクトとは... ガベージコレクタの仕組みを理解する:
https://www.atmarkit.co.jp/ait/articles/0404/02/news079.html
Slide 37
Slide 37 text
JMC で Java アプリケーションを解析する
❏ 「JVM 内部」→ 「ガベージコ
レクション」から、GC の統計
情報を取得することができる
GC ID / コレクタ名: “G1Full” が
表示されており、Full GC が頻発し
ている
最長の一時休止 / 一時停止合計: 実
行時間の経過に伴い、Full GC が頻
発しているためアプリケーション
の休止時間も増加傾向にある
Slide 38
Slide 38 text
ここまでのまとめ
❏ アプリケーションの実行時間が進むにつれ...
❏ FullGC が徐々に発生し始め、頻度が高くなる
❏ ヒープ使用率が徐々に増加している
❏ アプリケーションの休止時間が多くなる
❏ しかし原因の特定までは至っていない
Slide 39
Slide 39 text
❏ JFR / JMC を用いた解析で、徐々にヒープ使用率が上昇し
ていることがわかる
❏ 単にヒープサイズが足りないのが原因ではなさそう。
ヒープを増やしても問題の本質的な解決になならない
❏ 使用されているヒープのうち、何がヒープ上昇の原因と
なっているかを追求する
Next Action
Slide 40
Slide 40 text
ヒープダンプを取得し
Memory Analyzer で解析
Slide 41
Slide 41 text
❏ ヒープダンプを取得することで、ヒープの内訳を確認する
❏ ヒープダンプの取得方法は複数あるが、まずは OOME 発
生時にヒープダンプを生成してくれる
“-XX:+HeapDumpOnOutOfMemoryError” をつけて実
行してみる
ヒープダンプ を取得する
$ java \
-XX:+HeapDumpOnOutOfMemoryError \
-XX:HeapDumpPath=./output \
-Xms20M -Xmx20M -jar ./target/jdbc-bad-sample.jar
Slide 42
Slide 42 text
❏ 作成された .hprof ファイルは Memory Analyzer で解析す
ることができる
❏ Memory Analyzer は Eclipse Foundation のページ
(http://www.eclipse.org/mat/) からダウンロードが可能
.hprof ファイルを Memory Analyzer で解析する
http://www.eclipse.org/mat/
Slide 43
Slide 43 text
❏ 「File」→「Open File」から、先程作成された .hprof ファ
イルを開くと、以下のように解析された画面が表示される
❏ 円グラフの部分をクリックすると、どのオブジェクトがどの
くらいの割合を占めているかを確認することができる
.hprof ファイルを Memory Analyzer で解析する
Slide 44
Slide 44 text
❏ このヒープダンプが取られているのは OOME 発生時なので、一番割合
を占めているものが怪しい
❏ 一番割合が多い部分をクリックすると、
com.mysql.cj.jdbc.ConnectionImpl との記載がある。よって mysql
の接続処理に問題がありそうという目星をつけることができる。
.hprof ファイルを Memory Analyzer で解析する
Slide 45
Slide 45 text
❏ 「Actions」→「Histogram」を選択すると、Class の一
覧と Object 数、Object 単体のサイズ (Shallow
Heap)、Object が持つ他の Object を含めたサイズ
(Retained Heap) がリストで表示される
.hprof ファイルを Memory Analyzer で解析する
Slide 46
Slide 46 text
.hprof ファイルを Memory Analyzer で解析する
❏ Retained Heap の多い順にリストを並び替えると
java.lang.Object, CopyOnWriteArrayList の下に
com.mysql.cj.jdbc.~ のクラスが続いている
❏ ここから MySQL の Connection 周りで大きく heap を使ってい
ることがわかる
Slide 47
Slide 47 text
.hprof ファイルを Memory Analyzer で解析する
❏ 一番 heap を使っている java.lang.Object の "Merge
Shortest Path to GC Roots" を開くと、生存している
(GC の対象外となった) Object と、その Object が参照
している Object 群を階層構造で表示できる
Slide 48
Slide 48 text
.hprof ファイルを Memory Analyzer で解析する
❏ Main Thread を expand していく
と、”com.mysql.cj.jdbc.~” の
Object が大量に存在していること
がわかる
❏ ”ConnectionImpl”
❏ “ClientPreparedStatement”
❏ “ResultSetImpl”
❏ よって MySQL DB へ接続する処理
で、Connection 処理が適切に
close されていないのでは? とい
う仮説をたてることができる
Slide 49
Slide 49 text
仮説で浮かび上がった問題を解
消し、再度解析を実行する
Slide 50
Slide 50 text
❏ 問題が発生したアプリケーションのコードの
PreparedStatement, ResultSet が利用されている部分
を確認すると、確かに close 処理が記述されていない
❏ close 処理を実施したうえで、再度解析を実施してみる
OOME の原因を解消して再度解析する
PreparedStatement と
ResultSet の close 処理
をそれぞれ記載
Slide 51
Slide 51 text
❏ PreparedStatement と ResultSet の close 処理を行った
アプリケーションを実行すると、問題なく処理が完了した
❏ JFR で解析してみると以下のように、適切にメモリが開放さ
れていることがわかる
OOME の原因を解消して再度解析する
OOME 発生時に表示されていた赤い
「！」マークも今回は表示されていない
※ 「環境」→「プロセス」に表示されている
ものはローカル PC の CPU 使用率に起因し、
マシンで実行している他のアプリケーション
の影響も受けるので今回は対象外と考える
Slide 52
Slide 52 text
❏ 「ガベージ・コレクション」を確認しても、FullGC は発
生しておらず、休止期間も低下していることがわかる
OOME の原因を解消して再度解析する
Slide 53
Slide 53 text
❏ OOME は発生しないので、前回とは別の方法でヒープダン
プを取得する
❏ 処理の後半で jmap コマンドを実行し、ヒープダンプを取
得して Memory Analyzer で解析する
# ヒープダンプの生成前に FullGC を実施
$ jmap -dump:live,file=
# 以下のコマンドでも ヒープダンプを取得可能
$ jcmd GC.heap_dump
OOME の原因を解消してヒープダンプを取得
Slide 54
Slide 54 text
❏ 取得できた .hprof ファイルを Memory Analyzer で開いてみると、
ヒープ全体のサイズは 6.6MB と 20MB の上限まで余裕があり、円グ
ラフで一番割合が多い部分は java.lang.Thread (main) となっている
❏ OOME 発生時に Heap の多くの割合を占めていた
com.mysql.cj.jdbc.ConnectionImpl は見られない
OOME の原因を解消してヒープダンプを取得
※ 灰色の部分は Remainder とい
う、上位の割合を占めないその他
の Heap を合計したもの
Slide 55
Slide 55 text
❏ 前回同様「Histgram」から一番 heap を使っている
java.lang.Object の "Merge Shortest Path to GC Roots" を
開いて見てみても、”com.mysql.cj.jdbc” のオブジェクトは見
られない → OOME の問題は解消と判断できる
OOME の原因を解消して ヒープダンプ を取得
Slide 56
Slide 56 text
ここまでのまとめ
❏ JFR を有効にし、JMC を用いて解析を行うことでアプリ
ケーションがどのようなヒープ、GC の傾向によって
OOME エラーが発生したかを把握
❏ OOME 発生時にヒープダンプを取得することで、 OOME
の原因となっているオブジェクトを特定
❏ 原因と思われる箇所を修正し、再度同様の解析を実施して
問題が解消されていることを確認
Slide 57
Slide 57 text
JFR をより活用する
Slide 58
Slide 58 text
JFR でヒープ統計を有効にする
Slide 59
Slide 59 text
❏ 先程の例では 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 オプションを付けて起動
Slide 60
Slide 60 text
❏ “path-to-gc-roots=true” を有効にすると、実行の開始
時と終了時に Old ガベージ・コレクションがトリガーされ
るため、通常よりもパフォーマンスの悪化が発生する
❏ パフォーマンスの遅延を検証する際や、パフォーマンスを
悪化させてはいけない環境での実行は控える
JFR でヒープ統計を有効にする際の注意点
4 JFRを使用したパフォーマンスの問題のトラブルシューティング:
https://docs.oracle.com/javase/jp/9/troubleshoot/troubleshoot-performance-issues-using-jfr.htm
Slide 61
Slide 61 text
❏ “path-to-gc-roots=true” を有効にすると、「メモリー」か
ら「ヒープのライブ・セット傾向」「ライブ・オブジェクト
数」が表示される
JFR でヒープ統計を有効にする
Slide 62
Slide 62 text
❏ 「ヒープのライブ・セット傾向」では、メモリリー
クが発生するオブジェクトの候補が表示される
JFR でヒープ統計を有効にする
1つめのリーク候補:
“AbandonedConnectionCleanupThread$ConnectionFinalizerPha
ntomReference.networkResources”
が表示されている
2つめのリーク候補: ”JVMCI” から参照されている HashMap オブ
ジェクトが対象になっている。JVMCI は Java で JIT を作るための
インターフェースなので、今回は関係なさそう
(https://www.sakatakoichi.com/entry/2017/11/27/193000)
Slide 63
Slide 63 text
❏ 「ライブ・オブジェクト数」では、GC の対象外となるオ
ブジェクト (OOME の原因となりそうなオブジェクト) が
表示される
JFR でヒープ統計を有効にする
ライブ・オブジェクトのサンプル:
AbandonedConnectionCleanupT
hread というクラスに関するオブ
ジェクトが赤文字で表示されてお
り、OOME の原因と考えられる
Slide 64
Slide 64 text
❏ ヒープ統計の情報から、 AbandonedConnectionCleanupThread の
オブジェクトが増え続けているため、このオブジェクトが OOME の原
因ではないかという仮説も立つ
❏ 調べて見ると AbandonedConnectionCleanupThread は、放置され
た MySQL DB の Connection を close してくれる Thread で、度々
メモリリークの原因にもなっているよう
❏ 最初に調べたときは、この AbandonedConnectionCleanupThread
のバグを踏んだのかとも考えた
補足: AbandonedConnectionCleanupThread
MySQL Connector/J (JDBC ドライバ)の罠まとめ: https://saiya-moebius.hatenablog.com/entry/2014/08/20/2304
Slide 65
Slide 65 text
❏ しかし JMC の「Java アプリケーション」→「スレッド」を選択し、
mysql-cj-abandoned-connection-cleanup のスレッドを確認する
と、特にこのスレッドは実行されていないように見える
補足: AbandonedConnectionCleanupThread
Slide 66
Slide 66 text
❏ また、ヒープダンプを見た限りでは 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
Slide 67
Slide 67 text
JFR でより詳細な情報を取得する
Slide 68
Slide 68 text
❏ JFR を実行する際、デフォルトではオーバーヘッドの少な
い “${JAVA_HOME}/lib/jfr/default.jfc” が指定されて
実行される
❏ “${JAVA_HOME}/lib/jfr/profile.jfc” を指定すること
で、より詳細な情報が取得できる。.jfc ファイルの記述を
変更して取得情報のカスタマイズも可能。
❏ ただし詳細な情報を取得しようとすると、実行時のオーバー
ヘッドは大きくなるので注意
JFR でより詳細な情報を取得する
Slide 69
Slide 69 text
❏ 例えば “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
Slide 70
Slide 70 text
JFR でより詳細な情報を取得する
❏ 「ライブ・オブジェクトのサンプル」でリーク候補を選択
すると、スタックトレースが表示されるようになる
ライブ・オブジェクトのサンプル:
AbandonedConnectionCleanupThread
クラスに関するオブジェクトが赤文字で表
示されている
スタックトレース:
Main Thread から
java.sql.DriverManager.getConnection
という記載があり、Connection 周りで参
照されているオブジェクトにメモリリーク
の原因がありそうと推測できる
Slide 71
Slide 71 text
まとめ
Slide 72
Slide 72 text
❏ この発表では FullGC, OOME が発生するアプリケーショ
ンに対し、原因を突き止めるために JFR, JMC, Memory
Analyzer などのツールを用いた方法をご紹介した
❏ 参考文献、まとまった書籍などがなかなかない分野と感じ
ているので、皆様も是非情報発信していただけると嬉しい
です！
まとめ
Slide 73
Slide 73 text
❏ 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
Slide 74
Slide 74 text
ご清聴ありがとうございました