末永 恭正 @YaSuenag

https://www.flickr.com/photos/falcon_33/8988705269

#jdt2016_4A

OracleとJavaは、Oracle Corporation及びその子会社、関連会社の米国及びその他の国における登録商標です。文中の社名、商品名等は各社の商標または登録商標である場合があります。

••

•

•

••••

•http://icedtea.classpath.org/wiki/HeapStats/jp

Copyright © NTT COMWARE CORPORATION 2016NTT COMWARE CORPORATION CONFIDENTIAL PROPRIETARY

NTTコムウェアでも…

Javaアプリケーションの潜在的なバグ、チューニングについてコンサルティングします！

Java診断サービス

1番多い

メモリトラブルに対応！

一部の性能問題にも

対応可能

• サービス内容• メモリ枯渇の危険性やメモリに関連するAPの潜在的なバグの有無を確認

• Garbage Collection(GC)をはじめとした、JVMのチューニング実施• OSSのツールを活用し、突然のトラブルにも迅速に対応できる環境の実現に向けたコンサルティング

• 対象プロダクト• Oracle JDK 1.5以上• OpenJDK• JRockit R28以上※動作するミドル、ライブラリについては条件はありません。

NTTコムウェア 品質生産性技術本部 技術SE部 OSS・AP技術担当ctpm-se-openjdk-all@srv.cc.nttcom.co.jp043-211-2392

突然ですが

jcmd

jhsdb＆

情報収集・設定変更

プロセスハング解析

コア解析

jcmdjhsdb

•

••

• http://docs.oracle.com/javase/8/docs/technotes/guides/troubleshoot/tooldescr016.html#BABFCHDE

It is suggested to use the latest utility, jcmd instead of the previous jstack utility for enhanced diagnostics and reduced performance overhead.

http://docs.oracle.com/javase/jp/8/docs/technotes/tools/unix/jstack.html#BABBIIJD

http://docs.oracle.com/javase/jp/8/docs/technotes/tools/unix/s11-troubleshooting_tools.html#sthref327

コマンド 内容

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ドメイン

コマンド 内容

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ドメイン

コマンド 内容

ManagementAgent.status JMXエージェントの状態表示

JVMTI.agent_load JVMTIエージェントのロード

JVMTI.data_dump JVMTIのデータダンプ要求（DataDumpRequest）発行

GC.finalizer_info ファイナライザ実行待ちキューに入っているクラス情報の表示

GC.heap_info Javaヒープの概要表示

その他

ログの出力設定忘れちゃった！！

•• http://openjdk.java.net/jeps/158•

•

$ jcmd 1234 VM.log output="file=gc.log" ¥output_options="filecount=5,filesize=10m" ¥what="gc=debug" ¥decorators="time,level"

オプション名 内容

output 出力先”#<数字>”を指定すると既存のoutputに対する変更を意味する

output_options 出力オプション

what タグやログレベルの設定

decorators ログデコレーションの設定

•1.2.

••

$ jcmd 1234 VM.log rotate

$ jcmd 1234 VM.log list1234:Available log levels: off, trace, debug, info, warning, errorAvailable 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, workgangDescribed 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-8153074UL: Show output option in VM.log jcmd

障害解析に必要な情報を簡単に

収集させたい

••

•

•

•

$ jcmd 1234 VM.info1234:## 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-bitNarrow klass base: 0x0000000000000000, Narrow klass shift: 3Compressed class space size: 1073741824 Address: 0x0000000100000000

：

ヤバい！オプションつけ忘れた…

••

$ jcmd 1234 VM.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}

•

$ jcmd 1234 VM.set_flag HeapDumpOnOutOfMemoryError true1234:Command executed successfully$ jcmd 1234 VM.flags1234:-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-8155936Boolean value should be set 1/0 or true/false via VM.set_flag jcmd

JITを細かく制御して問題発生を

予防しましょうね

••

••

•

[{match: ["*String.hashCode"],

c2: {Exclude: true

}}

]

$ jcmd 1234 Compiler.directives_add compiler-directive.json1234:1 compiler directives added

•$ jcmd 1234 Compiler.directives_print1234:

Directive:

matching: *String.hashCodec1 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:falseVectorize: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:falseVectorize:false VectorizeDebug:false CloneMapDebug:false DoReserveCopyInSuperWordDebug:false IGVPrintLevel:0 MaxNodeLimit:80000

Enable ：ディレクティブの明示的設定Exclude ：JIT除外設定

オレのアプリ、どれぐらいJITの恩恵

受けてるんだ？

•$ jcmd 1234 Compiler.codelist1234:53 4 java.lang.String.hashCode()I [0x00007fd2cd776090, 0x00007fd2cd776200 - 0x00007fd2cd776398]

コンパイルID

コンパイルレベル（Tiered Compilation）

メソッド名nmethod

開始アドレスコード

開始アドレス

コード終了アドレス

••

• http://otndnld.oracle.co.jp/ondemand/javaday2014/pdf/C2-JavaDay-304328.pdf

さて、診断ツール仕込むか

••

••

•

••

• http://docs.oracle.com/javase/8/docs/jdk/api/attach/spec/index.html

•

•

0の意味：Agent_OnAttach()の戻り値http://docs.oracle.com/javase/jp/8/docs/platform/jvmti/jvmti.html#onattach

•

ヒープの状況をざっくり知りたい

••

•

••

$ jcmd 1234 GC.heap_info1234: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 1056768Kclass space used 328K, capacity 386K, committed 512K, reserved 1048576K

••

•

プロローグ（ファイルヘッダ） エントリ

•

"Attach Listener" #12 daemon prio=9 os_prio=0 tid=0x00007f3224001000 nid=0xb8f7 waiting on condition [0x0000000000000000]

java.lang.Thread.State: RUNNABLE

•• http://www.slideshare.net/YaSuenag/serviceability-tools

ターゲットプロセスがハングしたら動かない！

※PerfCounter.print以外

••

•

•

• S A•

• Java 9からは各種ツールでSAが使えなくなりました！

•

• OpenJDKのdebuginfoパッケージ必須

••

•

http://docs.oracle.com/javase/8/docs/serviceabilityagent/index.html

ツール名 概要

clhsdb コマンドライン版HotSpotデバッガ

hsdb GUI版HotSpotデバッガ

jstack SA版jstackjmap SA版jmapjinfo SA版jinfojsnap hsperfdataの読み取り

•••

•

••

••

••

•

••

•JDK-8151815Could not parse core image with JSnap.

•

(gdb) x/g ((G1CollectedHeap *)Universe::_collectedHeap)->_g1mm->_full_collection_counters->_time ->_valuep

0x7f8c6884b960: 15535194

例：Full GCの累計実行時間を出してみる（jstatのFGCT相当）

15535194÷1000000000≒0.015 (sec)

GCアルゴリズムによってカウンタへのポインタまでの辿り方違うのかよ…

OpenJDKのソースなんて読みたくねーよ…

•

$ $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ガンバってます！

HotSpot（C++）の世界とJavaの世界を

結びつけるのがタイヘン

••

••

•

••

••

••

•

•

••

•

••

•

••

•

Project Kenaiからのダウンロードはやめましょう！

••

•

https://kenai.com/projects/base-hsdis/downloads

Project Kenaiのもの Fedora23でビルドしたもの

StubRoutines::updateBytesCRC32

※OracleJDK 8u92 Linux x64で確認（-XX:+UnlockDiagnosticVMOptions -XX:+PrintStubCode）

Fedora23 x64の場合

$ dnf download --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.sobuild/linux-amd64/hsdis-amd64.so

binutilsのSRPM取得

SRPM展開

hsdisのビルド

hsdis本体

••

••

••

•• https://bugs.openjdk.java.net/

••

最後にもう1度

jcmd

jhsdb＆