Java 9で進化する診断ツール

Java 9で進化する診断ツール

• 1.
  末永 恭正 @YaSuenag https://www.flickr.com/photos/falcon_33/8988705269 #jdt2016_4A
• 2.
  OracleとJavaは、Oracle Corporation及びその子会社、関連会社の米国及びその他の国における登録商標です。 文中の社名、商品名等は各社の商標または登録商標である場合があります。 • • • •
• 3.
  • • • • • http://icedtea.classpath.org/wiki/HeapStats/jp
• 4.
  突然ですが jcmd jhsdb ＆
• 5.
  情報収集・設定変更 プロセスハング解析 コア解析 jcmd jhsdb
• 7.
  • • • • http://docs.oracle.com/javase/8/docs/technotes/guides/troubleshoot/toold escr016.html#BABFCHDE It issuggested to use the latest utility, jcmd instead of the previous jstack utility for enhanced diagnostics and reduced performance overhead.
• 8.
  http://docs.oracle.com/javase/jp/8/docs/technotes/tools/unix/jstack.html#BABBIIJD
• 9.
  http://docs.oracle.com/javase/jp/8/docs/technotes/tools/unix/s11-troubleshooting_tools.html#sthref327
• 10.
  コマンド 内容 VM.log ログ出力設定とローテーションの実行 VM.print_touched_methods実行されたメソッドの一覧表示 VM.classloader_stats クラスローダに関する情報の表示 VM.stringtable StringTable（String#intern()した文字列や解決した クラス名が入っているテーブル）の概要表示、ダンプ VM.symboltable SymbolTable（メソッド名等）の概要表示、ダンプ VM.class_hierarchy Javaヒープ中のクラス階層構造の表示 VM.info javaプロセスの詳細情報、およびマシン情報の表示 VM.dynlibs ロードされている共有ライブラリの出力 VM.set_flag フラグ（-XXオプション）の変更 VMドメイン
• 11.
  コマンド 内容 Compiler.directives_clear JITコンパイラへの指示をすべてクリア Compiler.directives_remove一番最後のJITコンパイラへの指示を削除 Compiler.directives_add JITコンパイラへの指示をJSON形式での指定 Compiler.directives_print JITコンパイラへの現在の指示内容の表示 Compiler.codecache コードキャッシュの概要の表示 Compiler.codelist コードキャッシュの内容表示 Compiler.queue JITコンパイラのコンパイル待ちキューにあるメソッドの 表示 Compilerドメイン
• 12.
  コマンド 内容 ManagementAgent.status JMXエージェントの状態表示 JVMTI.agent_loadJVMTIエージェントのロード JVMTI.data_dump JVMTIのデータダンプ要求（DataDumpRequest）発行 GC.finalizer_info ファイナライザ実行待ちキューに入っているクラス情報 の表示 GC.heap_info Javaヒープの概要表示 その他
• 14.
  ログの出力設定 忘れちゃった！！
• 15.
  • • http://openjdk.java.net/jeps/158 • •
• 16.
  $ jcmd 1234VM.log output="file=gc.log" output_options="filecount=5,filesize=10m" what="gc=debug" decorators="time,level" オプション名 内容 output 出力先 ”#<数字>”を指定すると既存のoutputに対する変更を意味する output_options 出力オプション what タグやログレベルの設定 decorators ログデコレーションの設定
• 17.
  • 1. 2. • • $ jcmd 1234VM.log rotate
• 18.
  $ jcmd 1234VM.log list 1234: Available log levels: off, trace, debug, info, warning, error Available log decorators: time (t), uptime (u), timemillis (tm), uptimemillis (um), timenanos (tn), uptimenanos (un), hostname (hn), pid (p), tid (ti), level (l), tags (tg) Available log tags: add, age, alloc, arguments, annotation, barrier, biasedlocking, bot, breakpoint, census, class, classhisto, cleanup, compaction, constraints, constantpool, coops, cpu, cset, data, defaultmethods, dump, ergo, exceptions, exit, freelist, gc, heap, humongous, ihop, iklass, init, itables, jni, jvmti, liveness, load, loader, logging, mark, marking, methodcomparator, metadata, metaspace, mmu, modules, monitorinflation, monitormismatch, nmethod, normalize, objecttagging, obsolete, oopmap, os, pagesize, path, phases, plab, promotion, preorder, protectiondomain, ref, redefine, refine, region, remset, purge, resolve, safepoint, scavenge, scrub, stacktrace, start, startuptime, state, stats, stringdedup, stringtable, stackmap, subclass, survivor, sweep, task, thread, tlab, time, timer, update, unload, verification, verify, vmoperation, vtables, workgang Described tag combinations: logging: Logging for the log framework itself Log output configuration: #0: stdout all=warning uptime,level,tags #1: stderr all=off uptime,level,tags #2: gc.log gc=debug filecount=5,filesize=20M level,tags JDK-8153074 UL: Show output option in VM.log jcmd
• 19.
  障害解析に必要な情報を 簡単に 収集させたい
• 20.
  • • • • •
• 21.
  $ jcmd 1234VM.info 1234: # # JRE version: Java(TM) SE Runtime Environment (9.0+119) (build 9-ea+119) # Java VM: Java HotSpot(TM) 64-Bit Server VM (9-ea+119, mixed mode, tiered, compressed oops, g1 gc, linux-amd64) --------------- S U M M A R Y ------------ Command Line: LongSleep Host: Intel(R) Core(TM) i3-2367M CPU @ 1.40GHz, 2 cores, 1G, Fedora release 23 (Twenty Three) Time: Mon May 23 20:32:22 2016 JST elapsed time: 16 seconds (0d 0h 0m 16s) --------------- P R O C E S S --------------- Heap address: 0x00000000e0e00000, size: 498 MB, Compressed Oops mode: 32-bit Narrow klass base: 0x0000000000000000, Narrow klass shift: 3 Compressed class space size: 1073741824 Address: 0x0000000100000000 ：
• 22.
  ヤバい！ オプションつけ忘れた…
• 23.
  • • $ jcmd 1234VM.flags -all | grep -E 'manageable|product_rw' intx CMSAbortablePrecleanWaitMillis = 100 {manageable} intx CMSTriggerInterval = -1 {manageable} intx CMSWaitDuration = 2000 {manageable} bool HeapDumpAfterFullGC = false {manageable} bool HeapDumpBeforeFullGC = false {manageable} bool HeapDumpOnOutOfMemoryError = false {manageable} ccstr HeapDumpPath = {manageable} uintx MaxHeapFreeRatio = 70 {manageable} uintx MinHeapFreeRatio = 40 {manageable} bool PrintClassHistogram = false {manageable} bool PrintConcurrentLocks = false {manageable}
• 24.
  • $ jcmd 1234VM.set_flag HeapDumpOnOutOfMemoryError true 1234: Command executed successfully $ jcmd 1234 VM.flags 1234: -XX:CICompilerCount=2 -XX:ConcGCThreads=1 -XX:G1HeapRegionSize=1048576 -XX:+HeapDumpOnOutOfMemoryError -XX:InitialHeapSize=33554432 -XX:MarkStackSize=4194304 -XX:MaxHeapSize=522190848 -XX:MaxNewSize=312475648 -XX:MinHeapDeltaBytes=1048576 -XX:NonNMethodCodeHeapSize=5824844 -XX:NonProfiledCodeHeapSize=122916698 -XX:ProfiledCodeHeapSize=122916698 -XX:ReservedCodeCacheSize=251658240 -XX:+SegmentedCodeCache -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC JDK-8155936 Boolean value should be set 1/0 or true/false via VM.set_flag jcmd
• 25.
  JITを細かく制御して 問題発生を 予防しましょうね
• 26.
  • • • •
• 27.
  • [ { match: ["*String.hashCode"], c2: { Exclude:true } } ]
• 28.
  $ jcmd 1234Compiler.directives_add compiler-directive.json 1234: 1 compiler directives added
• 29.
  • $ jcmd 1234Compiler.directives_print 1234: Directive: matching: *String.hashCode c1 directives: inline: - Enable:false Exclude:false BreakAtExecute:false BreakAtCompile:false Log:false PrintAssembly:false PrintInlining:false PrintNMethods:false BackgroundCompilation:true ReplayInline:false DumpReplay:false DumpInline:false CompilerDirectivesIgnoreCompileCommands:false DisableIntrinsic: BlockLayoutByFrequency:true PrintOptoAssembly:false PrintIntrinsics:false TraceOptoPipelining:false TraceOptoOutput:false TraceSpilling:false Vectorize:false VectorizeDebug:false CloneMapDebug:false DoReserveCopyInSuperWordDebug:false IGVPrintLevel:0 MaxNodeLimit:80000 c2 directives: inline: - Enable:true Exclude:true BreakAtExecute:false BreakAtCompile:false Log:false PrintAssembly:false PrintInlining:false PrintNMethods:false BackgroundCompilation:true ReplayInline:false DumpReplay:false DumpInline:false CompilerDirectivesIgnoreCompileCommands:false DisableIntrinsic: BlockLayoutByFrequency:true PrintOptoAssembly:false PrintIntrinsics:false TraceOptoPipelining:false TraceOptoOutput:false TraceSpilling:false Vectorize:false VectorizeDebug:false CloneMapDebug:false DoReserveCopyInSuperWordDebug:false IGVPrintLevel:0 MaxNodeLimit:80000 Enable ：ディレクティブの明示的設定 Exclude ：JIT除外設定
• 30.
  オレのアプリ、 どれぐらいJITの恩恵 受けてるんだ？
• 31.
  • $ jcmd 1234Compiler.codelist 1234: 53 4 java.lang.String.hashCode()I [0x00007fd2cd776090, 0x00007fd2cd776200 - 0x00007fd2cd776398] コンパイル ID コンパイルレベル （Tiered Compilation） メソッド名 nmethod 開始アドレス コード 開始アドレス コード 終了アドレス
• 32.
  • • • http://otndnld.oracle.co.jp/ondemand/javaday2014/pdf/C2- JavaDay-304328.pdf
• 33.
  さて、 診断ツール仕込むか
• 34.
  • • • • •
• 35.
  • • • http://docs.oracle.com/javase/8/docs/jdk/api/attach/spec/index.ht ml
• 36.
  •
• 37.
  • 0の意味： Agent_OnAttach()の戻り値 http://docs.oracle.com/javase/jp/8/docs/platfo rm/jvmti/jvmti.html#onattach
• 38.
  •
• 39.
  ヒープの状況を ざっくり知りたい
• 40.
  • • • • • $ jcmd 1234GC.heap_info 1234: garbage-first heap total 32768K, used 1024K [0x00000000e0e00000, 0x00000000e0f00100, 0x0000000100000000) region size 1024K, 2 young (2048K), 0 survivors (0K) Metaspace used 3332K, capacity 4486K, committed 4864K, reserved 1056768K class space used 328K, capacity 386K, committed 512K, reserved 1048576K
• 42.
  • • •
• 43.
  プロローグ（ファイルヘッダ） エントリ
• 44.
  • "Attach Listener" #12daemon prio=9 os_prio=0 tid=0x00007f3224001000 nid=0xb8f7 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE
• 45.
  • • http://www.slideshare.net/YaSuenag/serviceability-tools
• 46.
  ターゲットプロセスが ハングしたら動かない！ ※PerfCounter.print以外
• 48.
  • • • •
• 49.
  • S A • •Java 9からは各種ツールでSAが使えなくなりました！ • • OpenJDKのdebuginfoパッケージ必須 • • •
• 50.
  http://docs.oracle.com/javase/8/docs/serviceabilityagent/index.html
• 51.
  ツール名 概要 clhsdb コマンドライン版HotSpotデバッガ hsdbGUI版HotSpotデバッガ jstack SA版jstack jmap SA版jmap jinfo SA版jinfo jsnap hsperfdataの読み取り
• 52.
  • • • •
• 53.
  • • • •
• 54.
  • • • • • • JDK-8151815 Could not parsecore image with JSnap.
• 55.
  • (gdb) x/g ((G1CollectedHeap*)Universe::_collectedHeap)->_g1mm->_full_collection_counters->_time ->_valuep 0x7f8c6884b960: 15535194 例：Full GCの累計実行時間を出してみる（jstatのFGCT相当） 15535194÷1000000000≒0.015 (sec)
• 56.
  GCアルゴリズムによって カウンタへのポインタまでの辿り方 違うのかよ… OpenJDKのソースなんて 読みたくねーよ…
• 57.
  • $ $JAVA_HOME/bin/jhsdb jsnap--exe $JAVA_HOME/bin/java --core core.6937 --all | grep -a -e sun.gc.collector.1.time -e sun.os.hrt.frequency sun.gc.collector.1.time=15535194 tick(s) sun.os.hrt.frequency=1000000000 Hz 15535194÷1000000000≒0.015 (sec) この実現のためにJDK-8151815ガンバってます！
• 58.
  HotSpot（C++）の世界と Javaの世界を 結びつけるのがタイヘン
• 60.
  • • • • • • •
• 61.
  • •
• 62.
  • • • •
• 63.
  • • •
• 64.
  • • •
• 65.
  • • •
• 66.
  Project Kenaiからのダウンロードは やめましょう！
• 67.
  • • • https://kenai.com/projects/base-hsdis/downloads
• 68.
  Project Kenaiのもの Fedora23でビルドしたもの StubRoutines::updateBytesCRC32 ※OracleJDK8u92 Linux x64で確認（-XX:+UnlockDiagnosticVMOptions -XX:+PrintStubCode）
• 69.
  Fedora23 x64の場合 $ dnfdownload --source binutils $ rpm -ivh <binutils> $ cd ~/rpmbuild/SPECS $ rpmbuild -bp binutils.spec $ cd <OpenJDK src>/hotspot/src/share/tools/hsdis $ make BINUTILS=~/rpmbuild/BUILD/<binutils> ARCH=amd64 $ ls build/linux-amd64/hsdis-amd64.so build/linux-amd64/hsdis-amd64.so binutilsの SRPM取得 SRPM展開 hsdisのビルド hsdis本体
• 70.
  • • • •
• 72.
  • • • • https://bugs.openjdk.java.net/ • •
• 73.
  最後にもう1度 jcmd jhsdb ＆