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

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

toricky6
November 11, 2023

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

toricky6

November 11, 2023
Tweet

More Decks by toricky6

Other Decks in Programming

Transcript

  1. 本題 ヒープダンプ スレッド ダンプ ü Javaプロセスのある時点での全スレッドの情報を出⼒したもの ü スレッドの名前、状態、メソッドの呼び出し階層(スタックトレース)など を⾒ることができる ü

    jcmd、jstack、kill -3などで取得 事前の仕込みが不要で、その瞬間の「ヒープ状況」、その瞬間 に「動いていた処理」の状況が分かる︕原因究明が進む︕︕ ü Javaプロセスのメモリにあるすべてのオブジェクトのスナップショット ü ヒープ内にあるオブジェクトの容量・数・格納されている値などが分かる ü jcmd、コンソール画⾯などから取得
  2. Javaメモリ構造 ヒープ(-Xmx) ネイティブメモリ Young Old Eden Survivor Survivor Virtual Or

    reserved Virtual Or reserved Tenured ヒープ領域︓Javaオブジェクトや配列など動的に割り当てられたデータを格納 ネイティブ領域︓JVMが内部的な処理はJNIコードに利⽤。クラスのメタデータも格納 MetaSpace プロセス Other ヒープダンプ(今回のテーマ) ネイティブメモリ トラッキング(NMT)
  3. 【参考】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強あり
  4. メモリリークの診断⽅法 ヒープ・ヒストグラム ヒープダンプ フライトレコーダー クラスローダー統計 ü jcmdやjmapコマンドなどで取得が可能 ü コンソールから実⾏可能なため、即時切り分けには有効 ü

    ヒープ⼀式のスナップショットを取得。詳細分析可能 ü OpenJDK8、11+でデフォルト利⽤可能 ü 記録の開始・終了作業が必要 ü クラスローダー、および、ロードされるクラスの数 ü Metaspaceや圧縮クラス領域のメモリリーク診断
  5. ヒープ・ヒストグラム $jcmd <PID> GC.class_histogram にて取得可能。軽量︕ 緊急時の概況把握には効果的 $ jcmd 50575 GC.class_histogram

    50575: num #instances #bytes class name (module) ------------------------------------------------------- 1: 168094 9580856 [B ([email protected]) 2: 164873 3956952 java.lang.String ([email protected]) 3: 102016 3264512 jp.gihyo.projava.tasklist.HomeController$TaskItem 4: 4950 1661784 [C ([email protected]) 5: 12703 1377712 [Ljava.lang.Object; ([email protected]) 6: 13372 1176736 java.lang.reflect.Method ([email protected]) 7: 9658 1153184 java.lang.Class ([email protected]) 8: 30809 985888 java.util.concurrent.ConcurrentHashMap$Node ([email protected]) 9: 24563 982520 java.util.TreeMap$Entry ([email protected]) 10: 13316 532640 java.util.LinkedHashMap$Entry ([email protected]) 11: 4875 454736 [I ([email protected]) 3680: 1 16 sun.util.locale.provider.TimeZoneNameUtility$TimeZoneNameGetter ([email protected]) 3681: 1 16 sun.util.logging.internal.LoggingProviderImpl ([email protected]) 3682: 1 16 sun.util.resources.LocaleData$LocaleDataStrategy ([email protected]) 3683: 1 16 sun.util.resources.cldr.provider.CLDRLocaleDataMetaInfo ([email protected]) Total 762691 32777320 $
  6. ヒープダンプ取得⽅法 jcmd WebSphere jcmd <process id/main class> GC.heap_dump filen ame=heapdump.dmp

    ü wsadmin>generateHeapDump ü 管理コンソール>トラブルシューティング>Javaダンプおよびコ アより実施 OOME時に ⾃動出⼒ -XX:+HeapDumpOnOutOfMemoryError
  7. 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 [email protected] et(0) = 'j' 他にも複数・・・
  8. MATを使うときのコツ ü (経験的に多いのは)、開発者の実装コードよりも、ライブラリやミドルウェアの 設定考慮漏れや不具合。⾒慣れないクラスでも使⽤量を順に⾒ていく → 実はOSSライブラリがキャッシュする仕様だった、ステートメントキャッシュが⼤きかった → ドリルダウンしていき、valueを⾒ていると、⾒覚えあるクラスにぶつかることも ü ⽐較対象となるヒープダンプを、予め残しておくこと

    → 性能試験実施時、起動直後、停⽌直前など → 分析者が業務実装者でない場合ほど「平常か」「異常か」の判断の助け ü 格納されている値もセットで⾒ること → 開発者が実装していないクラスほど、値を⾒ること ü 格納されている数も評価すること → 意図した数量か、消し漏れか、実装誤りか・・・・
  9. スレッドダンプの前に・・・・ 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待ち) アプリケーション・サーバでは複数のスレッドで同時多数の処理をすることが⼀般的 当然、時間とともに処理は進む
  10. スレッドダンプ ヘッダー⾏ •スレッド名(アプリケーションサーバにより種々あり) •スレッドがデーモン・スレッドであるかどうか(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([email protected]/Native Method) at java.lang.ref.Reference.processPendingReferences([email protected]/Reference.java:245) at java.lang.ref.Reference$ReferenceHandler.run([email protected]/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([email protected]/Native Method) - waiting on <0x000000070037a1b0> (a java.lang.ref.NativeReferenceQueue$Lock) at java.lang.Object.wait([email protected]/Object.java:366) at java.lang.Object.wait([email protected]/Object.java:339) at java.lang.ref.NativeReferenceQueue.await([email protected]/NativeReferenceQueue.java:48) at java.lang.ref.ReferenceQueue.remove0([email protected]/ReferenceQueue.java:158) at java.lang.ref.NativeReferenceQueue.remove([email protected]/NativeReferenceQueue.java:89) - locked <0x000000070037a1b0> (a java.lang.ref.NativeReferenceQueue$Lock) at java.lang.ref.Finalizer$FinalizerThread.run([email protected]/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([email protected]/Native Method) at java.lang.Thread.sleep([email protected]/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([email protected]/LambdaForm$DMH) at java.lang.invoke.LambdaForm$MH/0x0000000801038400.invoke([email protected]/LambdaForm$MH) at java.lang.invoke.Invokers$Holder.invokeExact_MT([email protected]/Invokers$Holder) at jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl([email protected]/DirectMethodHandleAccessor.java: NEW スレッドはまだ開始されていません。 RUNNABLE スレッドはJVM内で実⾏されています。 BLOCKED スレッドはモニター・ロックを待機してブロックされてい ます。 WAITING スレッドは、別のスレッドが特定のアクションを実⾏す るのを無期限に待機しています。 TIMED_WAITING スレッドは指定された待機時間、別のスレッドがアク ションを実⾏するのを待機しています。 TERMINATED スレッドは終了しています。
  11. アプリケーションサーバで種々なスレッド名(⼀部) 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
  12. スレッドダンプ(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
  13. スレッドダンプ解析ツール TMDA (IBM Thread and Monitor Dump Analyzer for Java)

    侍 ü Javaチャンピオン(@yusuke)⽒作のOSS ü スレッド毎のステータスを可視化(他tailなど機能複数あり) ü Javaスレッドダンプからハング、デッドロック、リソース競 合、ボトルネックを可視化 ü TMDAは、スレッドの状態、スタックトレース、ロック状態 などの情報を提供します。 https://github.com/yusuke/samurai/tree/main