JJUG 2023 fall トラブルシューティング・ヒープダンプ・スレッドダンプ解析チューニング

Transcript

1. トラブルシューティング︕︕ ヒープダンプ・スレッドダンプ解析 チューニング JJUG CCC Fall 2023 2023/11/11 ⾦光 淳⼀郎
2. 障害、再起動で復旧することも多いですが・・・ ログから調査すると・・・ ①GCログ → ヒープの利⽤傾向が分かる ②アクセスログ →フルGC多発時のアクセスは分かる なんとなく、メモリを使うアクセスは分かる ③サーバログ→StackTheadから⼀定時間要した処理は分かる 仮説は(頑張れば)作れるが、証拠がない。。。
3. 本題 ヒープダンプ スレッド ダンプ ü Javaプロセスのある時点での全スレッドの情報を出⼒したもの ü スレッドの名前、状態、メソッドの呼び出し階層（スタックトレース）など を⾒ることができる ü jcmd、jstack、kill -3などで取得 事前の仕込みが不要で、その瞬間の「ヒープ状況」、その瞬間 に「動いていた処理」の状況が分かる︕原因究明が進む︕︕ ü Javaプロセスのメモリにあるすべてのオブジェクトのスナップショット ü ヒープ内にあるオブジェクトの容量・数・格納されている値などが分かる ü jcmd、コンソール画⾯などから取得
4. Javaメモリ構造 ヒープ(-Xmx) ネイティブメモリ Young Old Eden Survivor Survivor Virtual Or reserved Virtual Or reserved Tenured ヒープ領域︓Javaオブジェクトや配列など動的に割り当てられたデータを格納 ネイティブ領域︓JVMが内部的な処理はJNIコードに利⽤。クラスのメタデータも格納 MetaSpace プロセス Other ヒープダンプ（今回のテーマ） ネイティブメモリ トラッキング（NMT)
5. JavaGC⽅式 ParallelGC(–xx:UseParallelGC） Java8まで、マルチコア環境でデフォルトの⽅式。各領域のサイズの設定 マルチスレッドでマーク＆スイープとコンパクションを実施。 Young Old Eden Survivor Survivor Tenured
6. GarbageFirstGC(G1GC) Java9からデフォルトの⽅式。最⼤ヒープサイズとGC⽬標時間を設定。 ヒープ領域を複数の領域（リージョン）に分割。各領域のGCを並⾏して実⾏や、領域昇格により 停⽌時間を短縮。 ガベージファースト(G1)ガベージ・コレクタ (oracle.com)より抜粋 Eden領域(⾚)、サバイバー領域(⾚に「S」)、空き（灰⾊）、Old（⽔⾊） 複数領域にまたがるオブジェクト（⽔⾊H） Eden領域(⾚)、サバイバー領域(⾚に「S」)、空き（灰⾊）、Old（⽔⾊） 複数領域にまたがるオブジェクト（⽔⾊H） レイテンシー、スループット、サイズなどをチューニング。 ※Java Platform, Standard Edition HotSpot Virtual Machine Garbage Collection Tuning Guide, Release 21 (oracle.com)
7. 【参考】Javaオプションとデフォルト値の⼀覧取得 「java -XX:+PrintFlagsFinal 」にて取得可能 [Global flags] int ActiveProcessorCount = -1 {product} {default} uintx AdaptiveSizeDecrementScaleFactor = 4 {product} {default} uintx AdaptiveSizeMajorGCDecayTimeScale = 10 {product} {default} uintx AdaptiveSizePolicyCollectionCostMargin = 50 {product} {default} uintx AdaptiveSizePolicyInitializingSteps = 20 {product} {default} uintx AdaptiveSizePolicyOutputInterval = 0 {product} {default} uintx AdaptiveSizePolicyWeight = 10 {product} {default} uintx AdaptiveSizeThroughPutPolicy = 0 {product} {default} uintx AdaptiveTimeWeight = 25 {product} {default} bool AggressiveHeap = false {product} {default} bool AlignVector = false {C2 product} {default} ccstr AllocateHeapAt = {product} {default} intx AllocateInstancePrefetchLines = 1 {product} {default} intx AllocatePrefetchDistance = 256 {product} {default} （略） uintx MaxGCPauseMillis = 200 {product} {default} （略） size_t MinHeapSize = 16777216 {product} {ergonomic} （略） uintx SurvivorRatio = 8 {product} {default} ・・・・・ V21では500強あり
8. メモリの状況を確認する⽅法 リアルタイム︓JMC、VisualVM リモート接続時はサーバ側で設定要（※） ファイル参照︓GCViewer GCログの出⼒が必要 （※） 「JDK Mission Control ユーザーズ・ガイド 5 リモートJVMの操作」参照
9. アルゴリズムの違い ParallelGCの例 234秒で処理終了。ただし、GC時間は3秒以下 G1GCの例 264秒で処理終了。ただし、GC時間は1秒以下 Java21・Mac(2コア)で同⼀負荷をかけた際のGC結果の違い
10. メモリリークの診断⽅法 ヒープ・ヒストグラム ヒープダンプ フライトレコーダー クラスローダー統計 ü jcmdやjmapコマンドなどで取得が可能 ü コンソールから実⾏可能なため、即時切り分けには有効 ü ヒープ⼀式のスナップショットを取得。詳細分析可能 ü OpenJDK8、11+でデフォルト利⽤可能 ü 記録の開始・終了作業が必要 ü クラスローダー、および、ロードされるクラスの数 ü Metaspaceや圧縮クラス領域のメモリリーク診断
11. ヒープ・ヒストグラム $jcmd ＜PID＞ GC.class_histogram にて取得可能。軽量︕ 緊急時の概況把握には効果的 $ jcmd 50575 GC.class_histogram 50575: num #instances #bytes class name (module) ------------------------------------------------------- 1: 168094 9580856 [B (java.base@19.0.1) 2: 164873 3956952 java.lang.String (java.base@19.0.1) 3: 102016 3264512 jp.gihyo.projava.tasklist.HomeController$TaskItem 4: 4950 1661784 [C (java.base@19.0.1) 5: 12703 1377712 [Ljava.lang.Object; (java.base@19.0.1) 6: 13372 1176736 java.lang.reflect.Method (java.base@19.0.1) 7: 9658 1153184 java.lang.Class (java.base@19.0.1) 8: 30809 985888 java.util.concurrent.ConcurrentHashMap$Node (java.base@19.0.1) 9: 24563 982520 java.util.TreeMap$Entry (java.base@19.0.1) 10: 13316 532640 java.util.LinkedHashMap$Entry (java.base@19.0.1) 11: 4875 454736 [I (java.base@19.0.1) 3680: 1 16 sun.util.locale.provider.TimeZoneNameUtility$TimeZoneNameGetter (java.base@19.0.1) 3681: 1 16 sun.util.logging.internal.LoggingProviderImpl (java.logging@19.0.1) 3682: 1 16 sun.util.resources.LocaleData$LocaleDataStrategy (java.base@19.0.1) 3683: 1 16 sun.util.resources.cldr.provider.CLDRLocaleDataMetaInfo (jdk.localedata@19.0.1) Total 762691 32777320 $
12. ヒープダンプ取得⽅法 jcmd WebSphere jcmd <process id/main class> GC.heap_dump filen ame=heapdump.dmp ü wsadmin＞generateHeapDump ü 管理コンソール＞トラブルシューティング＞Javaダンプおよびコ アより実施 OOME時に ⾃動出⼒ -XX:+HeapDumpOnOutOfMemoryError
13. Eclipse Memory Analyzer Tool(MAT) メモリー・リークを検出する、⾼速で機能 豊富な Java ヒープ・アナライザー ダンプファイルを開くと⾃動的に解析 スタンドアロン版はJava17からサポート ヒープサイズが⼤きい場合はMemoryA nalyzer.iniの「-Xmx」を修正
14. ヒープファイルを開くと・・・Overview Retainedヒープ(後述) の解析結果 【Inspector】 右側のWindowに 合わせ詳細表⽰ 各種アクション・ レポートへのリンク 【Value】 格納される値を⾒て 詳細を判断可能
15. ヒストグラム クラス別にグループ化されたオブジェクトの⼀覧 ü シャロウ・ヒープ 1つのオブジェクトによって消費されるメモリー量 ü リテインド・ヒープ 1つ以上のオブジェクトに、そのオリジナル・オブジェクトからのみ (直接または間接的に) 参照されるオブジェクトを加えたもの
16. ドミネーターツリー（１／２） ツリー形式でドリルダウンが可能。調査の⼿がかりとして⾮常に便利。
17. ドミネーターツリー（２／２） 各クラスの属性や値も確認可能 変なクラスがあって、こんな値のクラスが⼀杯あるんだけど・・・と、調べが進む
18. その他︓いろんな事ができます① クラスローダでグルーピング すべての⾏の保持サイズを概算 outgoing/incoming 参照
19. その他︓いろんなことができます② スーパークラスでソート パッケージでソート
20. GC ルートへのパス ⻩⾊のドットで装飾されたオブジェクトは、ガベージ コレクション (GC) ルート。 ⽣きていると想定されるオブジェクト →「本来消えるべきものが、消えてないのでは︖」論争も無⽤。
21. OQL（Object Query Language) SQLライクなクエリでヒープダンプをクエリできるもの 構⽂ 概要 例 SELECT Clause Select specific columns SELECT toString(s), s.count, s.value FROM java.lang.String s Provide column names SELECT toString(s) AS Value, s.@usedHeapSize AS "Shallow Size", s.@retainedHeapSize AS "Retained Size" FROM java.lang.String s FROM Clause by class name: SELECT * FROM java.lang.String by a regular expression matching the class name: SELECT * FROM "java¥.lang¥..*" by the object address of the class: SELECT * FROM 0x2b7468c8 WHERE Clause >=, <=, >, <, [ NOT ] LIKE, [ NOT ] IN, IMPLEMENTS (relational operations) SELECT * FROM java.lang.String s WHERE ( s.count > 1000 ) = true OR toString(s) = "monday" OR dominators(s).size() = 0 OR s.@retainedHeapSize > 1024L OR s.value != null AND s. value.@valueArray.@length >= 1 AND s.value.@valueArray.g et(0) = 'j' 他にも複数・・・
22. OQLの使い⽅ OQLを書いて「F5」キー or 「ctrl+Enter」キー SELECT * FROM OBJECTS 85479,19793,42 1826,822701,398857,313578 OQLを⾃動⽣成
23. Leak Suspects(1/2） ヒープダンプを解析し、メモリリークの被疑箇所をピックアップする機能
24. Leak Suspects(2/2）
25. MATを使うときのコツ ü （経験的に多いのは）、開発者の実装コードよりも、ライブラリやミドルウェアの 設定考慮漏れや不具合。⾒慣れないクラスでも使⽤量を順に⾒ていく → 実はOSSライブラリがキャッシュする仕様だった、ステートメントキャッシュが⼤きかった → ドリルダウンしていき、valueを⾒ていると、⾒覚えあるクラスにぶつかることも ü ⽐較対象となるヒープダンプを、予め残しておくこと → 性能試験実施時、起動直後、停⽌直前など → 分析者が業務実装者でない場合ほど「平常か」「異常か」の判断の助け ü 格納されている値もセットで⾒ること → 開発者が実装していないクラスほど、値を⾒ること ü 格納されている数も評価すること → 意図した数量か、消し漏れか、実装誤りか・・・・
26. スレッドダンプの前に・・・・ Diagnostic Tools (oracle.com) 未使⽤（リクエスト待ち） SQL作成中 接続プール獲得待ち SQL実⾏中（DB待ち） 00:00:00.000 00:00:01.000 00:00:02.000 SQL実⾏中（DB待ち） 接続プール獲得待ち SQL実⾏中（DB待ち） 未使⽤（リクエスト待ち） SQL実⾏中（DB待ち） アプリケーション・サーバでは複数のスレッドで同時多数の処理をすることが⼀般的 当然、時間とともに処理は進む
27. スレッドダンプを⾒ると何が分かるか︖ 動いているコード スタックトレースより、どのクラスの何⾏⽬の処理が実⾏中か分かる 動いているか否か 同⼀スレッドに着⽬し、処理が動いているのか、否かが分かる。 例）DBのロールバック待ち・・・だが、応答がない( socket.read() ） リクエスト先の応答待ち・・・だが、NW障害があって応答がない ⼀定間隔毎に複数回取ること・・・・で 誰に待たされて いるのか ロックの状況や、処理コードより、原因が分かる 例）ハッシュマップの〇〇待ち 接続プールの空き待ち ユーザのNWが遅い・・・
28. スレッドダンプの取得⽅法 kill コンソールより kill -3 ＜pid> アプリケーションサーバのコンソール画⾯より取得 jstack -XX:+HeapDumpOnOutOfMemoryError
29. スレッドダンプ ヘッダー⾏ •スレッド名（アプリケーションサーバにより種々あり） •スレッドがデーモン・スレッドであるかどうか（daemon） •スレッドの優先順位 (prio) •メモリ内のスレッド構造のアドレス(tid) •ネイティブ・スレッドの ID (nid) •スレッドの状態 •スレッドの有効なスタック領域の推定値を⽰すアドレス範囲。 Diagnostic Tools (oracle.com) 2023-11-05 22:54:52 Full thread dump Java HotSpot(TM) 64-Bit Server VM (19.0.1+10-21 mixed mode, sharing): Threads class SMR info: _java_thread_list=0x00006000011103c0, length=33, elements={ 0x00007f86dc013c00, 0x00007f86dd00fc00, 0x00007f86dc80e800, 0x00007f86dc80ee00, 0x00007f86dc80f400, 0x00007f86dc811600, 0x00007f86dc811c00, 0x00007f86dc812200, 0x00007f86db008c00, 0x00007f86db00c200, 0x00007f86db0e2200, 0x00007f86dc1ac600, 0x00007f86dd0cf200, 0x00007f86dd27cc00, 0x00007f86dc1cfe00, 0x00007f86dd27d200, 0x00007f86dd265200, 0x00007f86dd1a6200, 0x00007f86dd264800, 0x00007f86dcb1e800, 0x00007f86dcb19a00, 0x00007f86dc459200, 0x00007f86dd28c000, 0x00007f86dc459800, 0x00007f86db54b400, 0x00007f86dc459e00, 0x00007f86db599800, 0x00007f86db599e00, 0x00007f86dd28c600, 0x00007f86db59a400, 0x00007f86dcb1b800, 0x00007f86dcb4d200, 0x00007f86dc085800 } "Reference Handler" #4 [19459] daemon prio=10 os_prio=31 cpu=2.95ms elapsed=47.76s tid=0x00007f86dc013c00 nid =19459 waiting on condition [0x0000700001a45000] java.lang.Thread.State: RUNNABLE at java.lang.ref.Reference.waitForReferencePendingList(java.base@19.0.1/Native Method) at java.lang.ref.Reference.processPendingReferences(java.base@19.0.1/Reference.java:245) at java.lang.ref.Reference$ReferenceHandler.run(java.base@19.0.1/Reference.java:207) "Finalizer" #5 [18435] daemon prio=8 os_prio=31 cpu=0.19ms elapsed=47.76s tid=0x00007f86dd00fc00 nid=18435 in O bject.wait() [0x0000700001b48000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait0(java.base@19.0.1/Native Method) - waiting on <0x000000070037a1b0> (a java.lang.ref.NativeReferenceQueue$Lock) at java.lang.Object.wait(java.base@19.0.1/Object.java:366) at java.lang.Object.wait(java.base@19.0.1/Object.java:339) at java.lang.ref.NativeReferenceQueue.await(java.base@19.0.1/NativeReferenceQueue.java:48) at java.lang.ref.ReferenceQueue.remove0(java.base@19.0.1/ReferenceQueue.java:158) at java.lang.ref.NativeReferenceQueue.remove(java.base@19.0.1/NativeReferenceQueue.java:89) - locked <0x000000070037a1b0> (a java.lang.ref.NativeReferenceQueue$Lock) at java.lang.ref.Finalizer$FinalizerThread.run(java.base@19.0.1/Finalizer.java:173) "http-nio-8080-exec-1" #35 [33283] daemon prio=5 os_prio=31 cpu=652.12ms elapsed=37.72s tid=0x00007f86dcb19a0 0 nid=33283 waiting on condition [0x0000700003491000] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep0(java.base@19.0.1/Native Method) at java.lang.Thread.sleep(java.base@19.0.1/Thread.java:465) at jp.gihyo.projava.tasklist.TaskListDao.findAll(TaskListDao.java:50) at jp.gihyo.projava.tasklist.HomeController.listItems(HomeController.java:43) at java.lang.invoke.LambdaForm$DMH/0x00000008011dc000.invokeVirtual(java.base@19.0.1/LambdaForm$DMH) at java.lang.invoke.LambdaForm$MH/0x0000000801038400.invoke(java.base@19.0.1/LambdaForm$MH) at java.lang.invoke.Invokers$Holder.invokeExact_MT(java.base@19.0.1/Invokers$Holder) at jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(java.base@19.0.1/DirectMethodHandleAccessor.java: NEW スレッドはまだ開始されていません。 RUNNABLE スレッドはJVM内で実⾏されています。 BLOCKED スレッドはモニター・ロックを待機してブロックされてい ます。 WAITING スレッドは、別のスレッドが特定のアクションを実⾏す るのを無期限に待機しています。 TIMED_WAITING スレッドは指定された待機時間、別のスレッドがアク ションを実⾏するのを待機しています。 TERMINATED スレッドは終了しています。
30. アプリケーションサーバで種々なスレッド名（⼀部） WebLogic WAS (J9) JBoss SpringBoot(Tomcat) Logback Default Finalizer Reference Handler LDAPConnThread WsSessionInvalidatorThread Signal Dispatcher Finalizer Thread NotificationServiceDispatcher Compiler Thread C2 CompilerThread0 MUTimer Deferrable Alarm Sweeper Thread Sweeper thread" Timer Concurrent Mark Helper Common-cleaner Common-Cleaner Weblogic.kernel.Default WebContainer Reference Reaper Notification Thread InteruptTimer Iprofiler MSC service thread Attach Listener DoSManager JIT Compilation Thread ServerService Monitor Deflation Thread VDE Transaction Processror Thread Timer DestroyJavaVM HikariPool-1 housekeeper Weblogic.socket.Muxer Jboss EL reference queue cleanup thread Management I/O Signal Dispatcher Weblogic.time.TimeEventGen erator JIT-SamplerThread Timer http-nio-8080-exec-1 GC task thread GC Slave GC Thread GC Thread
31. スレッドダンプ（IBM javacore) 0SECTION TITLE subcomponent dump routine NULL =============================== 1TICHARSET UTF-8 1TISIGINFO Dump Event "vmstop" (00000002) Detail "#0000000000000000" received 1TIDATETIMEUTC Date: 2021/04/23 at 18:02:44:017 (UTC) 1TIDATETIME Date: 2021/04/23 at 14:02:44:017 1TITIMEZONE Timezone: UTC-4 (EDT) 1TINANOTIME System nanotime: 379202644260787 1TIFILENAME Javacore filename: /home/doc-javacore/javacore.20210423.140244.1175.0001.txt 1TIREQFLAGS Request Flags: 0x81 (exclusive+preempt) 1TIPREPSTATE Prep State: 0x106 (vm_access+exclusive_vm_access+trace_disabled) (中略） NULL ------------------------------------------------------------------------ 0SECTION THREADS subcomponent dump routine NULL ================================= NULL 1XMPOOLINFO JVM Thread pool info: 2XMPOOLTOTAL Current total number of pooled threads: 19 2XMPOOLLIVE Current total number of live threads: 18 2XMPOOLDAEMON Current total number of live daemon threads: 15 NULL 1XMTHDINFO Thread Details NULL ... 3XMTHREADINFO "JIT Diagnostic Compilation Thread-007 Suspended" J9VMThread:0x0000000000035200, omrthread_t:0x00007F3F8C0D02C8, java/lang/Thread:0x00000000FFF42120, state:R, prio=10 3XMJAVALTHREAD (java/lang/Thread getId:0x9, isDaemon:true) 3XMJAVALTHRCCL sun/misc/Launcher$AppClassLoader(0x00000000FFF3BF98) 3XMTHREADINFO1 (native thread ID:0x618F, native priority:0xB, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000081) 3XMTHREADINFO2 (native stack address range from:0x00007F3F879C5000, to:0x00007F3F87AC5000, size:0x100000) 3XMCPUTIME CPU usage total: 0.052410771 secs, current category="JIT" 3XMHEAPALLOC Heap bytes allocated since last GC cycle=0 (0x0) 3XMTHREADINFO3 No Java callstack associated with this thread (中略） ... NULL 1XMTHDSUMMARY Threads CPU Usage Summary NULL ========================= 1XMTHDCATINFO Warning: to get more accurate CPU times for the GC, the option -XX:-ReduceCPUMonitorOverhead can be used. See the user guide for more information. NULL 1XMTHDCATEGORY All JVM attached threads: 0.698865000 secs 1XMTHDCATEGORY | 2XMTHDCATEGORY +--System-JVM: 0.653723000 secs 2XMTHDCATEGORY | | 3XMTHDCATEGORY | +--GC: 0.047248000 secs 2XMTHDCATEGORY | | 3XMTHDCATEGORY | +--JIT: 0.512971000 secs 1XMTHDCATEGORY | 2XMTHDCATEGORY +--Application: 0.045142000 secs ⼿元の環境で取得したら45万⾏・・・・ ・システム情報 ・内部イベントコールバック ・ネイティブメモリ情報 ・共有クラス ・メモリ情報 ・クラスローダー ・ロック ・他、障害情報 ・スレッド Java dump - IBM Documentation
32. スレッドダンプ解析ツール TMDA (IBM Thread and Monitor Dump Analyzer for Java) 侍 ü Javaチャンピオン(@yusuke)⽒作のOSS ü スレッド毎のステータスを可視化（他tailなど機能複数あり） ü Javaスレッドダンプからハング、デッドロック、リソース競 合、ボトルネックを可視化 ü TMDAは、スレッドの状態、スタックトレース、ロック状態 などの情報を提供します。 https://github.com/yusuke/samurai/tree/main
33. 侍の例 約3万⾏のスレッドダンプが整列されて、個別にクリックすると該当スレッドの スタックトレースが表⽰（超便利︕）
34. TMDAの例 侍 同様にマッピング表⽰を実施、また、各スナップショットも⾒やすくしてくれます JavaCoreの解析には不可⽋
35. 解析に向けて準備しておいた⽅が良いこと ü 本番環境の起動直後など、正常時のスレッドダンプ ü 本番環境の通常運⾏時のスレッドダンプ ü 異常時のスレッドダンプ（複数回） 余談︓10年ほど前、障害解析に備え数分毎にスレッドダンプを 取得するバッチを仕込んだところ、VM不具合を引いて コアダンプ・・・・。やりすぎは禁物
36. 最後、チューニング・・・ ヒープダンプから プログラム不具合修正（コーディング不具合） ミドルウェア・ライブラリ設定変更・不具合修正 ヒープサイズチューニング（領域拡張、サイズ割合変更） スレッドダンプから プログラム不具合修正（同期処理、⾮同期処理、ロック機構） ミドルウェア・ライブラリ設定変更・不具合修正 ミドルウェア設定変更（スレッド数、JDBC本数）
37. まとめ ü ヒープダンプを取得することで、Javaのヒープメモリの状況調査が可能です ü スレッドダンプを取得することで、その瞬間に動いていた処理の把握が可能です ü スレッドダンプは、かならず複数回取得しましょう。 ü ヒープダンプ・スレッドダンプとも、正常プロセスと、異常のあるプロセスの双⽅を 取得することで、初学者でも⽐較が可能です。