introduction to troubleshooting in jdk 9€¦ · 48 case5: native memory leak? copyright©2016 ntt...

Copyright©2016 NTT corp. and NTT COMWARE corp.

Introduction to Troubleshooting in JDK 9

Serviceability Tools are Your Friends

Yuji KUBOTA (@sugarlife)

Yasumasa Suenaga (@YaSuenag)

Shinji Takao

2

Who we are


KUBOTA Yuji (@sugarlife), hard-of-hearing

Senior Expert in NTT

OpenJDK Author (ykubota)IcedTea Committer

Shinji Takao

Senior Expert in NTT

IcedTea Committer

Yasumasa Suenaga (@YaSuenag)

Senior Expert in NTT COMWARE

OpenJDK Committer (ysuenaga)IcedTea Committer

https://twitter.com/sugarlife

https://twitter.com/yasuenag

3

#CON3733

Questions on twitter would begreatly appreciated!

Questions and comments


4

•Serviceability technology in Java 9

•Serviceability Tools• jhsdb

• jcmd

•HeapStats•Runtime monitoring tool powered by JVMTI

Topics:


Serviceability Technology


5

http://openjdk.java.net/groups/serviceability/

jcmd

jhsdb

jcmd

Today’s topics


6

http://openjdk.java.net/groups/serviceability/

•HotSpot collects data requested by serviceability tools•Serviceability tools

• Use methods implemented at sun.tools.attach.HotSpotVirtualMachine

•HotSpot• Request is received/processed on AttachListener

Dynamic Attach


7

Dynamic Attach (on Linux)

1. Send SIGQUIT

2. Start

AttachListener

thread

4. Processing

3. Send request

5. Receive response

Unix domain socketServiceability

Tool

Target

JVM

process


8

•aka PerfCounter

•Binaries of all statistics in HotSpot• /tmp/hsperfdata_<username>/<PID>

• jstat and jcmd refer to this file

jvmstat Performance Counters


9

•Library for collecting data from native layer• Like a native debugger (e.g. GDB)

•Debug symbol is required• debuginfo needs when you use OpenJDK on Linux

•SA can collect data from:•Memory dump (core file)

•Hung process

Serviceability Agent (SA)


10

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

Empty…


11

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

•Available via jhsdb ONLY•No –F option

SA in Java 9

JDK-8155091: Remove SA related functions from tmtools


12

$ jstack -F 999Error: -F option usedCannot connect to core dump or remote debug server. Use jhsdb jstack instead

https://bugs.openjdk.java.net/browse/JDK-8155091

13

Serviceability Tools

• jhsdb

• jcmd


jhsdbSA launcher in Java 9


14

•New troubleshooting tool in Java 9• Launcher for all SA tools

•Enables hangs and crashes to be analyzed

jhsdb

JDK-8059038: Create new launcher for SA tools


15

https://bugs.openjdk.java.net/browse/JDK-8059038

Mode of jhsdb

Mode

(1st argument)

Previous tool Abstract

clhsdb sa-jdi.jar HotSpot command-line debugger

hsdb sa-jdi.jar HotSpot GUI debugger

debugd jsadebugd SA debug server

jstack jstack Prints Java thread stack

jmap jmap Collects memory details

jinfo jinfo Prints VM information

jsnap sa-jdi.jar Dumps PerfCounter


16

Case 1: Obtain thread dump


17

$ jhsdb jstack --pid 999Attaching to process ID 999, please wait...Debugger attached successfully.Server compiler detected.JVM version is 9-internal+0-2016-08-16-100008.ysuenaga.hsDeadlock Detection:

No deadlocks found.

Thread 18083: (state = BLOCKED)- java.lang.Object.wait(long) @bci=0 (Interpreted frame)

:

Case 2: Obtain class histogram


18

$ jhsdb jmap --pid 999 --histoAttaching to process ID 999, please wait...Debugger attached successfully.Server compiler detected.JVM version is 9-internal+0-2016-08-03-150733.ysuenaga.hsIterating over heap. This may take a while...Object Histogram:

num #instances #bytes Class description--------------------------------------------------------------------------1: 3075 153392 byte[]2: 3530 112960 java.util.HashMap$Node

:

Case 3: Obtain heap dump


19

$ jhsdb jmap --pid 999 --binaryheap --dumpfile heapdump.hprofAttaching to process ID 999, please wait...Debugger attached successfully.Server compiler detected.JVM version is 9-internal+0-2016-08-03-150733.ysuenaga.hsheap written to heapdump.hprof

Case 4: Obtain VM information


20

$ jhsdb jinfo --pid 999Attaching to process ID 999, please wait...

:Java System Properties:

awt.toolkit = sun.awt.X11.XToolkitjava.specification.version = 9sun.management.compiler = HotSpot 64-Bit Tiered Compilers

:VM Flags:Non-default VM flags: -XX:CICompilerCount=3 -XX:ConcGCThreads=1

:Command line: -Xlog:gc=debug -XX:+HeapDumpOnOutOfMemoryError

Case 5: Attach to memory dump


21

$ jhsdb jstack --exe /path/to/java/executable ¥--core /path/to/memory/dump/core.999

Attaching to core core.999 from executable /path/to/java/executable, please wait...Debugger attached successfully.Server compiler detected.

:

HSDBDo you want to analyze in more details?


22

•GUI HotSpot Debugger•CLHSDB: Command Line HotSpot Debugger

•You can attach HSDB and CLHSDB to:• live process

•memory dump

• remote debug server (jsadebugd)

HSDB


23

•Windows Error Reporting (WER) enabled:•You have to set Full dump to DumpType

• https://msdn.microsoft.com/en-us/library/bb787181.aspx

•You have to pass -XX:+UseOSErrorReporting

•WER disabled:• If you do NOT run app on Windows Server, you have to pass -XX:+CreateCoredumpOnCrash

NOTE: for Windows


24

https://msdn.microsoft.com/en-us/library/bb787181.aspx

Find crashed thread

Click!

Crash thread name


25

Show call stacks

1. Choose

2. Click!

3. Call stack

4. Byte Codes


26

Show class histogram


27

Show VM Settings


28

See also:https://bitbucket.org/javamagazine/magdownloads/downloads/2012-07-JavaMag-ServiceabilityAgent.pdf


29

https://bitbucket.org/javamagazine/magdownloads/downloads/2012-07-JavaMag-ServiceabilityAgent.pdf

30

jcmdNearly the ultimate serviceability tool


31

•Recommend tool for diagnosing problems

jcmd


http://download.java.net/java/jdk9/docs/technotes/guides/troubleshoot/tooldescr.html

32


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

33


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

35

• jcmd -help•Prints basic usage

• jcmd target help• Lists available commands

•Depends on JVM version of target, not jcmd

• jcmd target help command•Prints command help

Help


36

Command: Domain.suffix (Java 8)


DomainNum.

suffixAbstract

PerfCounter 1 Performance Counter

ManagementAgent 3 JMX agent

Thread 1 Thread dump

GC 7 Heap / GC / Finalization

VM 7 Runtime info. (log/native mem/flag/etc.)

37

Command: Domain.suffix (Java 9)


DomainNum.

suffixAbstract

PerfCounter 1 - Performance Counter

ManagementAgent 4 +1 JMX agent

Thread 1 - Thread dump

GC 8 +2

-1

Heap / GC / Finalization

VM 15 +8 Runtime info. (log/native mem/flag/etc.)

Compiler 7 - JIT Compiler

JVMTI 2 - JVMTI agent

Removed GC.rotate_log

38


Traditional tool jcmd command Abstracts

jps -l Lists JVM Process

jstat PerfCounter.print Prints JVM statistics

jstack Thread.print Prints full thread dump

jmap -dump:file=file

jmap -histo:live

GC.heap_dump file

GC.class_histogram

Dumps the Java heap

Prints a histogram of the heap

jinfo

jinfo -flag

jinfo -flags

jinfo -sysprops

PerfCounter.print

VM.set_flag

VM.flags

VM.system_properties

Prints VM information

Sets JVM flag

Lists configured JVM flags

Lists system properties

Alternatives to traditional tools

39

• jcmd 999 VM.log [options]

Case1: Oops, I forgot to set GC.log!


Options Description

output The name or index (#<index>) of output to configure.

output_options Options for the output

what Configures what tags to log

decorators Configures which decorators to use

disable Clears all configurations and turns off all loggings

list Lists current log configurations

rotate Rotate all logs (instead of GC.log_rotate in Java 8)

40



•Confirms current loggings

$ jcmd 999 VM.log list999:Available log levels: off, trace, debug, info, warning, errorAvailable log decorators: time (t), uptime (u), timemillis (tm), …Available log tags: add, age, alloc, arguments, annotation, barrier, …: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

default configurations

41



•Turns on a new logging: GC.log$ jcmd 999 VM.log output="file=gc.log"

output_options="filecount=5,filesize=10m"what="gc=debug" decorators="time,level"

999:Command executed successfully$ jcmd 999 VM.log list999:: Log output configuration:#0: stdout all=warning uptime,level,tags#1: stderr all=off uptime,level,tags#2: gc.log gc=debug time,level added a new logging

tag=log_level

name or path

options (log rotate)

42



•Turns off all existing loggings

• If you want to turn off #2 only• jcmd 999 VM.log output="#2" what="all=off"

$ jcmd 999 VM.log disable999:Command executed successfully$ jcmd 999 VM.log list999::

Log output configuration:#0: stdout all=off uptime,level,tags#1: stderr all=off uptime,level,tags

set all=off at stdout / stderr, and removed

the other configuration(s) such as #2

output nothing

43

• jcmd 999 VM.log rotate

•Rotates logs satisfying the following1. Configured ‘output’ as file

2. Configured ‘filecount’ (by ‘output_option’)

Case2: Force logrotate manually


$ jcmd 999 VM.log list: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

#2 will be rotated,

not #0 and #1

Obsoleted GC.rotate_log

44

•Use ManagementAgent domain• jcmd 999 ManagementAgent.start [jmxremote.*]

Case3: Control JMX after goes live


suffix Description

status Prints JMX agent’s status

start Enables remote JMX access

start_local Enables local JMX access

stop Disables remote JMX access (not local)

45

Case3: Control JMX after goes live


$ jcmd 999 ManagementAgent.start jmxremote.port=777 jmxremote.ssl=true999:Commandexecuted successfully$ jcmd 999 ManagementAgent.statusAgent: enabled

Connection Type: remoteProtocol : rmiHost : fedora24.novalocalURL : service:jmx:rmi://XXX…XXXProperties :

com.sun.management.jmxremote.authenticate = true [default]com.sun.management.jmxremote.ssl.need.client.auth = false [default]com.sun.management.jmxremote.ssl = true [default]:com.sun.management.jmxremote.port = 8070

You can set these

properties by option

46

•Use DiagnosticCommandMBean with jconsole / jvisualvm

Case4: Can I run jcmd to remote?


same as jcmd

commands

click then run jcmd

VM.system_properties

result

47

•Use VM.native_memory command1. Run Java with -XX:NativeMemoryTracking=summary

2. jcmd 999 VM.native_memory baseline

3. jcmd 999 VM.native_memory summary.diff

• More details by using ‘detail’ instead of ‘summary’

•NativeMemoryTracking was available since Java 8• https://docs.oracle.com/javase/8/docs/technotes/

guides/troubleshoot/tooldescr007.html

Case5: Native memory leak?


https://docs.oracle.com/javase/8/docs/technotes/guides/troubleshoot/tooldescr007.html

48



$ jcmd 999 VM.native_memory baseline999:Baseline succeeded# --- Run process/method which wants to check the memory consumption ---$ jcmd 999 VM.native_memory summary.diff999:Native Memory Tracking:Total: reserved=5664359KB -36096KB, committed=371555KB -36096KB- Java Heap (reserved=4108288KB, committed=258048KB)

(mmap: reserved=4108288KB, committed=258048KB)- Class (reserved=1056953KB +15KB, committed=5433KB +15KB)

(classes #767 +3)(malloc=185KB +3KB #741 -4)(mmap: reserved=1056768KB, committed=5248KB)

- Thread (reserved=36128KB -112KB, committed=36128KB -112KB)(thread #36 +1)(stack: reserved=35980KB +325KB, committed=35980KB+325KB)(malloc=107KB +2KB #197 +4)(arena=41KB -130KB #70 +2)

:


±n shows diff from baseline

49

• jcmd 999 VM.info•prints a fatal error log that includes …

Case6: Get unified info. at once!


includes information

Version and configuration

Threads list and their state

Heap summary, JVM internal events (e.g.: GC, JIT, safepoint, etc…)

Memory map with loaded native libraries

VM arguments and environment variables

Details about the operation system and hardware

Thread dump and heap dump

are NOT included

https://docs.oracle.com/javase/8/docs/technotes/guides/troubleshoot/felog.html

•Use JVMTI domain

Case7: Operates JVMTI agent

suffix Description

agent_load <library_path> <option> Attach JVMTI agent of library path

data_dump Fire DataDumpRequest JVMTI

event


50

•Ex: Attach JVMTI agent to JShell



51



52

•Pros•Can configure JVM after it goes live

•Can print / dump various JVM information

•Can analyze hung process / Memory Dump

•By only two serviceability tools jhsdb and jcmd

•Cons• Insufficient time series information

Serviceability technology overview


53

54

HeapStatsLightweight JVMTI agent


https://github.com/HeapStats/heapstats

55

•Gathers runtime information continuously, then draws up time-series graphs

•Lightweight agent to run on the production systems

•New solution to troubleshooting for OpenJDK users.

HeapStats


http://www.irasutoya.com/2015/12/blog-post_168.html


http://3.bp.blogspot.com/-qzx9BMg9gxQ/UxbLz4cvIzI/AAAAAAAAeE4/QPfCtKS3UuI/s800/happy_woman6.png




56

SPECjvm2008 Composite Result


467.59 461.43

0

50

100

150

200

250

300

350

400

450

500

Without HeapStats With HeapStats

(ops/m)

1.32 %

Overhead Rate

57


$ jcmd 999 JVMTI.agent_load libheapstats.so999:Commandexecuted successfully

or

java.lang.OutOfMemoryError: Java heap space

$ java –jar heapstats-analyzer.jar

$ rpm -ivh heapstats-2.0.1-0.*.rpm$ java -agentpath:heapstats … Your_Application

then

How to use HeapStats



58


59


byte[]byte[]

60


byte[]

Most doubtful class which has many references to byte[]

61


Monitor wait

RunSleep

Legend

62

•https://github.com/HeapStats/heapstats

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

Your contributions are welcome!



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

63

•New troubleshooting for java 9•Can configure JVM after it goes live

•Can print / dump various JVM information

•Can profile hung JVM process

•By only two serviceability tools: jhsdb and jcmd

•HeapStats•Useful time series info. for after-the-fact analysis

Conclusion


introduction to troubleshooting in jdk 9€¦ · 48 case5: native memory leak? copyright©2016 ntt...

Documents