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
2. The opinions and views expressed in this talk are my own, and do not necessarily reflect the opinions or views of my employer.
3. • Landscape • Flags • Threads • OOME • Questions? Agenda
4. • Oracle HotSpot • OpenJDK HotSpot • Oracle JRockit * • IBM JVM • Azul Systems Zing JVM * • Waratek CloudVM * Landscape - JVMs
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
6. Landscape - Challenges
7. App Servers Message Queues Caches Schedulers Workers Data Stores Clients
8. #### Assumption is the mother of all F***UPS! - Travis Dane
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/
10. * Images Credit: Wikimedia Commons
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
12. The JVM
13. JPDA - Platform Debugger Architecture * http://docs.oracle.com/javase/6/docs/technotes/guides/jpda/architecture.html
14. JPDA - Platform Debugger Architecture * http://docs.oracle.com/javase/6/docs/technotes/guides/jpda/architecture.html
15. • Profiling, debugging, monitoring, thread analysis, coverage analysis, etc. JVM TI - JVM Tool Interface
16. • Profiling, debugging, monitoring, thread analysis, coverage analysis, etc. ! • Native Agents - Full » -agentlib:<agent-lib-name>=<options> » -agentpath:<path-to-agent>=<options> » hprof, jdwp agents included JVM TI - JVM Tool Interface
17. • Profiling, debugging, monitoring, thread analysis, coverage analysis, etc. ! • Native Agents - Full » -agentlib:<agent-lib-name>=<options> » -agentpath:<path-to-agent>=<options> » 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
18. JVM TI - JVM Tool Interface TI Agent I JVM TI Agent II event action event action TI Client Attach API load agent
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
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
21. JMX - Java Management Extensions http://docs.oracle.com/javase/7/docs/api/java/lang/management/package-summary.html
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=<resolvable_from_clients> ! Attach API ! Unless -XX:+DisableAttachMechanism
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
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
25. • jhat • JConsole • VisualVM • MissionControl (JDK >= 7u40) HotSpot - Graphical Tools
26. Vendor Tools - Sample set
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
28. * Image Credit: Wikimedia Commons
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<size> set initial Java heap size -Xmx<size> set maximum Java heap size -Xss<size> set java thread stack size -Xprof output cpu profiling data … Flags
31. -XX are not stable and are subject to change without notice ! Boolean -XX:+<option> or -XX:-<option> ! Numeric -XX:<option>=<number>[unit] Unit: ‘k’, ‘K’, ‘m’, ‘M’, ‘g’, ‘G’ - 32768 or 32k ! String -XX:<option>=<string> Flags
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
33. • ms • mx • PermSize • MaxPermSize • NewSize • MaxNewSize • NewRatio • UseCompressedOps • HeapDumpOnOutOfMemoryError • HeapDumpPath Flags - Memory
34. Flags - GC Logging • verbose:gc • loggc • PrintGCDetails • PrintGCTimeStamps • PrintGCDateStamps • UseGCLogFileRotation • NumberOfGCLogFiles=10 • GCLogFileSize=50M • PrintTenuringDistribution • PrintGCApplicationStoppedTime
35. Flags - GC • verbose:class • TraceClassLoading • TraceClassUnloading • TraceClassResolution • UseParallelGC • UseParallelOldGC • UseParNewGC • UseConcMarkSweepGC • GCTimeLimit • GCHeapFreeLimit
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
37. Flags - Demo
38. * Image Credit: Wikimedia Commons
39. Threads Type Regular Daemon
40. Threads Type Regular Daemon Name Automatic Custom *
41. Threads Type Regular Daemon Name Automatic Custom * Parent Group Not Null*
42. Threads Type Regular Daemon Name Automatic Custom * Parent Group Not Null* Priority MIN - NORM - MAX
43. Threads Type Regular Daemon Name Automatic Custom * Parent Group Not Null* Priority MIN - NORM - MAX State Thread.State
44. Thread States NEW RUNNABLE TERMINATED BLOCKED WAITING TIMED_WAITING
45. Thread Dump $ jstack <pid> $ jcmd <pid> Thread.print (JDK 7+) ! Output to terminal ! $ kill -3 <pid> or kill -SIGQUIT <pid> ! Outputs to JVM’s stdout ! JMX ! VisualVM, JConsole, etc.
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)
47. Thread Dump » Dump identifier ! » Application Threads !
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)
49. Thread Dump » Dump identifier ! » Application Threads ! » VM Threads
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.
51. Thread Dump » Dump identifier ! » Application Threads ! » VM Threads ! » JNI References Count ! JNI global references: 759
52. Thread Dump » Dump identifier ! » Application Threads ! » VM Threads ! » JNI References Count ! » Heap Utilization Summary *
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)
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)
55. Threads - Demo
56. OOEM
57. Exception in thread "main" java.lang.OutOfMemoryError: <Reason> OOEM - Flavors
58. • Java heap space OOEM - Flavors
59. • Java heap space • PermGen space OOEM - Flavors
60. • Java heap space • PermGen space • GC overhead limit exceeded OOEM - Flavors
61. • Java heap space • PermGen space • GC overhead limit exceeded • unable to create new native thread OOEM - Flavors
62. • Java heap space • PermGen space • GC overhead limit exceeded • unable to create new native thread • Requested array size exceeds VM limit • request <size> bytes for <reason>. Out of swap space? • <reason> <stack trace> (Native method) • Direct buffer memory OOEM - Flavors
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/
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
65. • Containers » Classloaders leaks ! • Frameworks » Reflection » Dynamic proxies OOEM - Application Runtime
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
67. Heap Demo
68. • JVM Fundamentals • Tools of the trade • Instrument the app • Telemetry • Culture Summary
69. Questions ? Ovidiu Dimulescu ! @odimulescu www.odimulescu.com
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