Threads, Needles, Stacks, Heaps

Troubleshooting Java applications has the reputation of a dark art and is often compared to finding the needle in a haystack. Using tools bundled with the JDK and the OS, a few open source packages and lightweight approaches can help you zero in on a some common scenarios. We will explore working with local and remote JVMs, the myriad of startup flags, analyzing and correlating thread dumps with cpu consumption, system vs application level instrumentation, getting around in an unfamiliar production environment and if we don’t forget, memory games.
If you could use more visibility into your Java application during development and production runs this talk is filled with practical tips, from the high level to the gritty details.

Transcript

1. !
   !
   !
   Threads, Needles, Stacks, Heaps
   DevNexus, 2014
   Ovidiu Dimulescu
   
   !
   @odimulescu
   
   www.odimulescu.com
   

   View Slide

2. The opinions and views expressed in this talk
   are my own, and do not necessarily reflect the
   opinions or views of my employer.
   

   View Slide

3. • Landscape
   
   • Flags
   
   • Threads
   
   • OOME
   
   • Questions?
   Agenda
   

   View Slide

4. • Oracle HotSpot
   
   • OpenJDK HotSpot
   
   • Oracle JRockit *
   
   • IBM JVM
   
   • Azul Systems Zing JVM *
   
   • Waratek CloudVM *
   Landscape - JVMs
   

   View Slide

5. • Why is the application slow?
   
   • Why does the application have hiccups?
   
   • Why is CPU pegged?
   
   • Why are we running out of memory?
   
   • …
   
   • Why _______ ?
   Landscape - Pain points
   

   View Slide

6. Landscape - Challenges
   

   View Slide

7. App Servers
   Message Queues
   Caches
   Schedulers
   Workers
   Data Stores
   Clients
   

   View Slide

8. ####
   Assumption is the mother of all F***UPS!
   - Travis Dane
   

   View Slide

9. ####
   Measure Anything, Measure Everything
   !
   “ If Engineering at Etsy has a religion, it’s the Church of
   Graphs. If it moves, we track it …”
   http://codeascraft.com/2011/02/15/measure-anything-measure-everything/
   

   View Slide

10. * Images Credit: Wikimedia Commons
    

    View Slide

11. • Complex apps architecture and environments
    
    • Insufficient historical data
    
    • Weak inter-systems correlation
    
    • Platforms disparity
    
    • No one size fits all
    
    • Folklore, outdated information
    
    • High barrier to entry for effective diagnostics
    Landscape - Challenges
    

    View Slide

12. The JVM
    

    View Slide

13. JPDA - Platform Debugger Architecture
    * http://docs.oracle.com/javase/6/docs/technotes/guides/jpda/architecture.html
    

    View Slide

14. JPDA - Platform Debugger Architecture
    * http://docs.oracle.com/javase/6/docs/technotes/guides/jpda/architecture.html
    

    View Slide

15. • Profiling, debugging, monitoring, thread analysis, coverage
    analysis, etc.
    JVM TI - JVM Tool Interface
    

    View Slide

16. • Profiling, debugging, monitoring, thread analysis, coverage
    analysis, etc.
    !
    • Native Agents - Full
    » -agentlib:=
    
    » -agentpath:=
    
    » hprof, jdwp agents included
    JVM TI - JVM Tool Interface
    

    View Slide

17. • Profiling, debugging, monitoring, thread analysis, coverage
    analysis, etc.
    !
    • Native Agents - Full
    » -agentlib:=
    
    » -agentpath:=
    
    » hprof, jdwp agents included
    
    !
    • Java Agents - Instrumentation only (java.lang.instrument.*)
    » -javaagent:agent-name.jar
    
    » multiple supported, management-agent.jar provided
    JVM TI - JVM Tool Interface
    

    View Slide

18. JVM TI - JVM Tool Interface
    TI Agent I
    JVM
    TI Agent II
    event
    action
    event
    action
    TI Client
    Attach API
    load
    agent
    

    View Slide

19. JMX - Java Management Extensions
    MBeanServer
    Standard
    
    MBeans
    Dynamic
    
    MBeans
    MXBeans
    Connector Connector Adaptor Adaptor
    Probes
    Agent
    Clients
    Remote
    Management
    JMX
    
    Console
    Custom
    
    Console
    RMI HTTP
    Browser
    HTTP
    SNMP
    SNMP
    J
    V
    M
    

    View Slide

20. JMX - Java Management Extensions
    MBeanServer
    Standard
    
    MBeans
    Dynamic
    
    MBeans
    MXBeans
    Connector Connector Adaptor Adaptor
    Probes
    Agent
    Clients
    Remote
    Management
    JMX
    
    Console
    Custom
    
    Console
    RMI HTTP
    Browser
    HTTP
    SNMP
    SNMP
    J
    V
    M
    

    View Slide

21. JMX - Java Management Extensions
    http://docs.oracle.com/javase/7/docs/api/java/lang/management/package-summary.html
    

    View Slide

22. JMX - Java Management Extensions
    Explicit
    !
    -Dcom.sun.management.jmxremote
    
    -Dcom.sun.management.jmxremote.authenticate=false
    
    -Dcom.sun.management.jmxremote.port=1234
    
    -Dcom.sun.management.jmxremote.ssl=false
    
    -Dcom.sun.management.jmxremote.password.file=/path/to/pw/file
    
    -Dcom.sun.management.jmxremote.access.file=/path/to/access/file
    
    -Djava.rmi.server.hostname=
    
    !
    Attach API
    !
    Unless -XX:+DisableAttachMechanism
    

    View Slide

23. JMX - Java Management Extensions
    • De facto standard
    
    • Wide support
    • RMI not firewall friendly, dynamic ports
    
    • RMI connector heavy, Observer effect
    
    • MBeans need to behave
    

    View Slide

24. • jcmd (JDK 7+)
    • jinfo
    
    • jhat
    
    • jmap
    
    • jps
    
    • jstat / jstatd
    
    • jstack
    HotSpot - Command Line Tools
    http://docs.oracle.com/javase/7/docs/webnotes/tsg/TSG-VM/html/tooldescr.html
    

    View Slide

25. • jhat
    
    • JConsole
    
    • VisualVM
    
    • MissionControl (JDK >= 7u40)
    HotSpot - Graphical Tools
    

    View Slide

26. Vendor Tools - Sample set
    

    View Slide

27. Heap Analysers
    !
    » MAT
    
    » Heapster
    
    » HeapAudit
    Open Source Tools
    GC Visualization
    !
    » VisualVM
    
    » GCViewer
    
    » GCHisto
    
    » gcviz
    JMX Clients
    !
    » MC5J
    
    » VisualVM
    
    » jmxterm
    
    » CRaSH
    Code Libraries *
    !
    » Coda Hale Metrics
    
    » Javalution
    
    » Trove
    
    » FastUtil
    

    View Slide

28. * Image Credit: Wikimedia Commons
    

    View Slide

29. View Slide

30. -X are non-standard, not guaranteed to be supported on all VM
    implementations, and are subject to change without notice in
    subsequent releases of the JDK.
    
    !
    $ java -X
    
    …
    
    -Xloggc:<file> log GC status to a file with time stamps
    
    -Xms set initial Java heap size
    
    -Xmx set maximum Java heap size
    
    -Xss set java thread stack size
    
    -Xprof output cpu profiling data
    
    …
    Flags
    

    View Slide

31. -XX are not stable and are subject to change without notice
    
    !
    Boolean
    
    
    -XX:+ or -XX:-
    
    !
    Numeric
    
    
    -XX:=[unit]
    
    
    Unit: ‘k’, ‘K’, ‘m’, ‘M’, ‘g’, ‘G’ - 32768 or 32k
    
    !
    String
    
    -XX:=
    
    Flags
    

    View Slide

32. $ java -XX:+PrintFlagsInitial -version
    
    $ java -XX:+PrintFlagsFinal -version
    
    $ java -XX:+PrintCommandLineFlags -version
    
    !
    • product - An officially supported, internal JVM option
    
    • rw - Dynamically writable
    
    • C1 - Client JIT Compiler
    
    • C2 - Server JIT Compiler
    
    • pd - Platform Dependent
    
    • lp64 - 64bit VM only
    
    • manageable - Externally defined and dynamically writable
    
    • diagnostic - VM debugging
    
    • experimental - Not officially supported
    
    !
    -XX:+UnlockExperimentalVMOptions
    
    -XX:+UnlockDiagnosticVMOptions
    Flags
    

    View Slide

33. • ms
    
    • mx
    
    • PermSize
    
    • MaxPermSize
    
    • NewSize
    
    • MaxNewSize
    
    • NewRatio
    
    • UseCompressedOps
    
    • HeapDumpOnOutOfMemoryError
    
    • HeapDumpPath
    Flags - Memory
    

    View Slide

34. Flags - GC Logging
    • verbose:gc
    
    • loggc
    
    • PrintGCDetails
    
    • PrintGCTimeStamps
    
    • PrintGCDateStamps
    
    • UseGCLogFileRotation
    
    • NumberOfGCLogFiles=10
    
    • GCLogFileSize=50M
    
    • PrintTenuringDistribution
    
    • PrintGCApplicationStoppedTime
    

    View Slide

35. Flags - GC
    • verbose:class
    
    • TraceClassLoading
    
    • TraceClassUnloading
    
    • TraceClassResolution
    
    • UseParallelGC
    
    • UseParallelOldGC
    
    • UseParNewGC
    
    • UseConcMarkSweepGC
    
    • GCTimeLimit
    
    • GCHeapFreeLimit
    

    View Slide

36. Legacy
    !
    -Xdebug
    
    -Xrunjdwp:transport=dt_socket,server=y,suspend=y,address=host:port
    
    !
    Modern
    !
    -agentlib:jdwp=transport=dt_socket,server=y,suspend=y,address=host:port
    
    !
    Help
    !
    $ java -agentlib:jdwp=help
    Flags - Debugging
    

    View Slide

37. Flags - Demo
    

    View Slide

38. * Image Credit: Wikimedia Commons
    

    View Slide

39. Threads
    Type
    Regular
    Daemon
    

    View Slide

40. Threads
    Type
    Regular
    Daemon
    Name
    Automatic
    Custom *
    

    View Slide

41. Threads
    Type
    Regular
    Daemon
    Name
    Automatic
    Custom *
    Parent Group Not Null*
    

    View Slide

42. Threads
    Type
    Regular
    Daemon
    Name
    Automatic
    Custom *
    Parent Group Not Null*
    Priority MIN - NORM - MAX
    

    View Slide

43. Threads
    Type
    Regular
    Daemon
    Name
    Automatic
    Custom *
    Parent Group Not Null*
    Priority MIN - NORM - MAX
    State Thread.State
    

    View Slide

44. Thread States
    NEW
    RUNNABLE
    TERMINATED
    BLOCKED
    WAITING
    TIMED_WAITING
    

    View Slide

45. Thread Dump
    $ jstack
    $ jcmd Thread.print (JDK 7+)
    !
    Output to terminal
    
    !
    $ kill -3 or kill -SIGQUIT
    !
    Outputs to JVM’s stdout
    
    !
    JMX
    !
    VisualVM, JConsole, etc.
    

    View Slide

46. Thread Dump
    » Dump identifier
    !
    2014-02-15 15:05:42
    Full thread dump Java HotSpot(TM) 64-Bit Server VM (24.45-b08 mixed mode)
    

    View Slide

47. Thread Dump
    » Dump identifier
    !
    » Application Threads
    !
    

    View Slide

48. Thread Dump
    "main" prio=5 tid=0x0000000101028800 nid=0x507 runnable [0x00007fff5fbfd000]
    
    java.lang.Thread.State: RUNNABLE
    
    at org.eclipse.swt.internal.cocoa.OS.objc_msgSend_bool(Native Method)
    
    at org.eclipse.swt.internal.cocoa.NSRunLoop.runMode(NSRunLoop.java:42)
    
    at org.eclipse.swt.widgets.Display.sleep(Display.java:4565)
    
    at org.eclipse.ui.application.WorkbenchAdvisor.eventLoopIdle(WorkbenchAdvisor.java:364)
    
    at org.eclipse.ui.internal.ide.application.IDEWorkbenchAdvisor.eventLoopIdle(IDEWorkbenchAdvisor.java:917)
    
    at org.eclipse.ui.internal.Workbench$3.eventLoopIdle(Workbench.java:459)
    
    at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine$9.run(PartRenderingEngine.java:1026)
    
    at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:332)
    
    at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.run(PartRenderingEngine.java:916)
    
    at org.eclipse.e4.ui.internal.workbench.E4Workbench.createAndRunUI(E4Workbench.java:86)
    
    at org.eclipse.ui.internal.Workbench$5.run(Workbench.java:585)
    
    at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:332)
    
    at org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:540)
    
    at org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:149)
    
    at org.eclipse.ui.internal.ide.application.IDEApplication.start(IDEApplication.java:124)
    
    at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:196)
    
    at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:110)
    
    at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:79)
    
    at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:353)
    
    at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:180)
    
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
    
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    
    at java.lang.reflect.Method.invoke(Method.java:606)
    
    at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:629)
    
    at org.eclipse.equinox.launcher.Main.basicRun(Main.java:584)
    
    at org.eclipse.equinox.launcher.Main.run(Main.java:1438)
    

    View Slide

49. Thread Dump
    » Dump identifier
    !
    » Application Threads
    !
    » VM Threads
    

    View Slide

50. Thread Dump
    "C2 CompilerThread1" daemon prio=5 tid=0x0033 nid=0x6703 waiting on condition [0x0000000000000000]
    
    java.lang.Thread.State: RUNNABLE
    
    !
    "C2 CompilerThread0" daemon prio=5 tid=0x0011 nid=0x6503 waiting on condition [0x0000000000]
    
    java.lang.Thread.State: RUNNABLE
    
    !
    "Signal Dispatcher" daemon prio=5 tid=0x0022 nid=0x6303 runnable [0x0000000000000000]
    
    java.lang.Thread.State: RUNNABLE
    
    !
    "Finalizer" daemon prio=5 tid=0x0044 nid=0x5f03 in Object.wait() [0x000000010b88b000]
    
    java.lang.Thread.State: WAITING (on object monitor)
    
    !
    "Reference Handler" daemon prio=5 tid=0x0055 nid=0x5d03 in Object.wait() [0x000000010b788000]
    
    java.lang.Thread.State: WAITING (on object monitor)
    
    !
    "VM Thread" prio=5 tid=0x0066 nid=0x5b03 runnable
    
    !
    "GC task thread#0 (ParallelGC)" prio=5 tid=0x000000010102d000 nid=0x5303 runnable
    
    !
    "GC task thread#1 (ParallelGC)" prio=5 tid=0x0000000101038800 nid=0x5503 runnable
    
    !
    "GC task thread#2 (ParallelGC)" prio=5 tid=0x0000000101039000 nid=0x5703 runnable
    
    !
    "GC task thread#3 (ParallelGC)" prio=5 tid=0x0000000101039800 nid=0x5903 runnable
    
    !
    "VM Periodic Task Thread" prio=5 tid=0x0000000101058000 nid=0x6b03 waiting on condition
    In general the VM thread is in one of three states: waiting to execute a VM operation, synchronizing all threads in preparation for a VM
    operation, or executing a VM operation. If you suspect that a hang is a HotSpot VM bug rather than an application or class library
    deadlock, then pay special attention to the VM thread.
    

    View Slide

51. Thread Dump
    » Dump identifier
    !
    » Application Threads
    !
    » VM Threads
    !
    » JNI References Count
    !
    JNI global references: 759
    

    View Slide

52. Thread Dump
    » Dump identifier
    !
    » Application Threads
    !
    » VM Threads
    !
    » JNI References Count
    !
    » Heap Utilization Summary *
    

    View Slide

53. Thread Dump
    PSYoungGen total 75776K, used 69708K [0x07f55, 0x07fb48, 0x08)
    
    eden space 75264K, 92% used [0x07f550,0x07f98fb028,0x07f9e8)
    
    from space 512K, 18% used [0x07fa18,0x07fa1980,0x07fa20)
    
    to space 11264K, 0% used [0x07fa98,0x07fa98,0x07fb48)
    
    !
    ParOldGen total 59392K, used 46432K [0x07e0, 0x07e3a0, 0x07f550)
    
    object space 59392K, 78% used [0x07e0,0x07e2d58270,0x07e3a0)
    
    !
    PSPermGen total 71680K, used 47149K [0x07d0, 0x07d460, 0x07e0)
    
    object space 71680K, 65% used [0x07d0,0x07d2e0b6c8,0x07d460)
    

    View Slide

54. Thread Dump
    “Thread I" prio=5 tid=0x0100 nid=0x1ef runnable [0x01acff]
    
    java.lang.Thread.State: RUNNABLE
    
    !
    “Thread 3" prio=5 tid=0x0300 nid=0x3dd in Object.wait() [0x0366]
    
    java.lang.Thread.State: TIMED_WAITING (on object monitor)
    
    !
    “Thread 4" prio=5 tid=0x0400 nid=0x4ab in Object.wait() [0x0477]
    
    java.lang.Thread.State: WAITING (on object monitor)
    
    !
    “Thread 5" prio=5 tid=0x0500 nid=0x5bd waiting for monitor entry [0x0523]
    
    java.lang.Thread.State: BLOCKED (on object monitor)
    
    !
    “Thread 2" prio=5 tid=0x0200 nid=0x2ef waiting on condition [0x02b8]
    
    java.lang.Thread.State: TIMED_WAITING (sleeping)
    
    !
    “Thread 6" prio=5 tid=0x0600 nid=0x6ef waiting on condition [0x06b8]
    
    java.lang.Thread.State: TIMED_WAITING (sleeping)
    

    View Slide

55. Threads - Demo
    

    View Slide

56. OOEM
    

    View Slide

57. Exception in thread "main" java.lang.OutOfMemoryError:
    OOEM - Flavors
    

    View Slide

58. • Java heap space
    OOEM - Flavors
    

    View Slide

59. • Java heap space
    • PermGen space
    OOEM - Flavors
    

    View Slide

60. • Java heap space
    • PermGen space
    • GC overhead limit exceeded
    OOEM - Flavors
    

    View Slide

61. • Java heap space
    • PermGen space
    • GC overhead limit exceeded
    • unable to create new native thread
    OOEM - Flavors
    

    View Slide

62. • Java heap space
    • PermGen space
    • GC overhead limit exceeded
    • unable to create new native thread
    • Requested array size exceeds VM limit
    
    • request bytes for . Out of swap space?
    
    • (Native method)
    
    • Direct buffer memory
    OOEM - Flavors
    

    View Slide

63. Guilty until proven innocent
    * Image Credit: http://www.sodahead.com/living/which-do-you-think-is-more-important-in-the-running-of-a-society-garbage-collector-or-surgeon/question-3564735/
    

    View Slide

64. • Sizing
    » Heap Areas (Eden, Old, PermGen, etc.)
    
    » Tenuring Threshold
    
    » Thread Stack
    
    !
    • Collectors choice
    » Type (Parallel, ParallelOld, CMS, G1)
    
    » Options (# of threads, etc.)
    OOEM - JVM Configuration
    

    View Slide

65. • Containers
    » Classloaders leaks
    
    !
    • Frameworks
    » Reflection
    
    » Dynamic proxies
    OOEM - Application Runtime
    

    View Slide

66. • Objects structure overhead
    !
    • Collections waste
    » Fill ratio consideration
    
    » Never shrink
    
    » Up to 2 x expansion algorithms
    
    !
    • Use of Finalizers, 2 x GC cycles
    OOEM - Application
    

    View Slide

67. Heap Demo
    

    View Slide

68. • JVM Fundamentals
    
    • Tools of the trade
    
    • Instrument the app
    
    • Telemetry
    
    • Culture
    Summary
    

    View Slide

69. Questions ?
    Ovidiu Dimulescu
    
    !
    @odimulescu
    
    www.odimulescu.com
    

    View Slide

70. http://www.kdgregory.com/index.php?page=java.outOfMemory
    
    http://www.infoq.com/articles/Java_Garbage_Collection_Distilled
    
    http://java-is-the-new-c.blogspot.com/2013/07/tuning-and-benchmarking-java-7s-garbage.html
    
    http://blog.ragozin.info/2012/10/safepoints-in-hotspot-jvm.html
    
    https://code.google.com/p/java-allocation-instrumenter/
    
    https://weblogs.java.net/blog/kcpeppe/archive/2013/12/11/case-study-jvm-hotspot-flags
    
    http://resources.ej-technologies.com/jprofiler/help/doc/indexRedirect.html?http&&&resources.ej-technologies.com/jprofiler/help/doc/helptopics/config/
    background.html
    
    http://openjdk.java.net/groups/hotspot/docs/RuntimeOverview.html
    
    http://docs.oracle.com/javase/7/docs/platform/jvmti/jvmti.html
    
    http://docs.oracle.com/javase/7/docs/webnotes/tsg/TSG-VM/html/toc.html
    
    http://docs.oracle.com/javase/7/docs/technotes/guides/rmi/faq.html
    
    http://olegz.wordpress.com/2009/03/23/jmx-connectivity-through-the-firewall/
    
    http://www.uml-diagrams.org/examples/java-6-thread-state-machine-diagram-example.html
    
    http://www.javacodegeeks.com/2012/03/jvm-how-to-analyze-thread-dump.html
    
    http://www.javabeat.net/introduction-to-java-agents/
    
    https://blog.heroku.com/archives/2013/12/3/end_monolithic_app
    
    http://openjdk.java.net/jeps/137
    
    http://docs.oracle.com/javase/7/docs/technotes/guides/jfr/toc.html
    
    http://www.youtube.com/playlist?list=PLKCk3OyNwIzsEVDq6zErLW7HSkY7aqdeT
    Resources
    

    View Slide