Thursday, May 7, 2015

Flame Graphs with Java Flight Recordings

Flame Graphs


Brendon D. Gregg, who is a computer performance analyst, has created Flame Graphs to visualize stack traces in an interactive way.

You must watch his talk at USENIX/LISA13, titled Blazing Performance with Flame Graphs, which explains Flame Graphs in detail.

There can be different types of flame graphs and I'm focusing on CPU Flame Graphs with Java in this blog post.

Please look at the Flame Graphs Description to understand the Flame Graph visualization.

CPU Flame Graphs and Java Stack Traces


As Brendon mentioned in his talk, understanding why CPUs are busy is very important when analyzing performance. 

CPU Flame Graphs is a good way to identify hot methods from sampled stack traces.

In order to generate CPU Flame Graphs for Java Stack Traces, we need a way to get sample stack traces.

Brendon has given examples to use jstack and Google's lightweight-java-profiler. Please refer to his perl program on generating CPU Flame Graphs from jstack and his Java Flame Graphs blog post on using the lightweight-java-profiler.

While trying out these examples, I was thinking whether we can generate a CPU Flame Graph from a Java Flight Recording Dump.

Hot Methods and Call Tree tabs in Java Mission Control are there to get an understanding of "hot spots" in your code. But I was really interested to see a Flame Graph visualization by reading the JFR dump. In this way, you can quickly see "hot spots" by using the Flame Graph software.

Note: JFR's method profiler is sampling based.


Parsing Java Flight Recorder Dump


In order to get sample stack traces, I needed a way to read a JFR dump (The JFR dump is a binary file).

I found a way to parse JFR dump file and output all data into an XML file. 

java oracle.jrockit.jfr.parser.Parser -xml /temp/sample.jfr > recording.xml

Even though, this is an easy way, it takes more time and the resulting XML file is quite large. For example, I parsed a JFR dump around 61MB and the XML was around 5.8GB!

Then I found out about the Flight Recorder Parsers from Marcus Hirt's blog.

There are two ways to parse a JFR file.

  1. Using the Reference Parser - This API is available in Oracle JDK
  2. Using the JMC Parser - This is available in Java Mission Control.

For more info, see the Marcus' blog posts on Parsers. He has also given an example for Parsing Flight Recordings.

As stated in his blog, these APIs are unsupported and there is a plan to release a proper Parsing API with JMC 6.0 and JDK 9.

Converting JFR Method Profiling Samples to FlameGraph compatible format.


I wrote a simple Java program to read a JFR file and convert all stack traces from "Method Profiling Samples" to FlameGraph compatible format.

I used the JMC Parser in the program. I couldn't find a way to get Method Profiling Samples using the Reference Parser. I was only able to find the "vm/prof/execution_sample" events from the reference parser and there was no way to get the stack trace from that event.

The JMC Parser was very easy to use and I was able to get the stack traces without much trouble.

The code is available at https://github.com/chrishantha/jfr-flame-graph. Please refer the README file for complete instructions on building, running and generating a FlameGraph from a JFR dump.

Following is the FlameGraph created from a sample JFR dump.


Flame Graph Reset Zoom org.wso2.example.JavaThreadCPUUsage.HeavyThread.run():27 (117 samples, 24.43%) org.wso2.example.. java.lang.Long.(init)(long):684 (5 samples, 1.04%) sun.security.provider.ByteArrayAccess.b2iBig64(byte[], int, int[]):274 (3 samples, 0.63%) sun.security.provider.NativePRNG$RandomIO.implNextBytes(byte[]):272 (3 samples, 0.63%) java.security.SecureRandom.nextBytes(byte[]):466 (77 samples, 16.08%) java.secur.. java.util.Random.(init)(long):120 (1 samples, 0.21%) sun.security.provider.SecureRandom.engineNextBytes(byte[]):208 (1 samples, 0.21%) java.util.Random.(init)():90 (21 samples, 4.38%) j.. sun.security.provider.MD5.(init)():66 (1 samples, 0.21%) sun.security.provider.NativePRNG$RandomIO.implNextBytes(byte[]):280 (2 samples, 0.42%) java.lang.StringBuilder.(init)():85 (8 samples, 1.67%) java.security.Provider$Service.newInstance(java.lang.Object):1240 (1 samples, 0.21%) java.lang.Thread.run():745 (479 samples, 100.00%) java.lang.Thread.run():745 sun.security.provider.SHA.implDigest(byte[], int):103 (40 samples, 8.35%) sun... java.lang.Long.toHexString(long):177 (29 samples, 6.05%) ja.. org.wso2.example.JavaThreadCPUUsage.LightThread.run():22 (26 samples, 5.43%) or.. sun.security.provider.DigestBase.engineDigest(byte[], int, int):186 (41 samples, 8.56%) sun... org.wso2.example.JavaThreadCPUUsage.LightThread.run():20 (18 samples, 3.76%) sun.security.provider.ByteArrayAccess.b2iLittle64(byte[], int, int[]):142 (2 samples, 0.42%) sun.security.provider.SecureRandom.engineNextBytes(byte[]):236 (7 samples, 1.46%) java.lang.Class.getConstructor0(java.lang.Class[], int):2897 (1 samples, 0.21%) java.lang.StringCoding.encode(char[], int, int):387 (2 samples, 0.42%) sun.security.provider.DigestBase.engineUpdate(byte[], int, int):121 (1 samples, 0.21%) sun.security.provider.NativePRNG$RandomIO.implNextBytes(byte[]):274 (58 samples, 12.11%) sun.sec.. java.io.FileInputStream.read(byte[], int, int):269 (3 samples, 0.63%) java.util.Random.seedUniquifier():97 (15 samples, 3.13%) java.security.MessageDigest$Delegate.engineUpdate(byte[], int, int):580 (11 samples, 2.30%) sun.security.provider.MD5.implCompress(byte[], int):148 (9 samples, 1.88%) all (479 samples, 100%) java.util.Random.nextInt(int):307 (1 samples, 0.21%) java.lang.Long.valueOf(long):574 (3 samples, 0.63%) java.lang.reflect.Constructor.newInstance(java.lang.Object[]):526 (1 samples, 0.21%) sun.security.jca.GetInstance.getInstance(java.security.Provider$Service, java.lang.Class):236 (3 samples, 0.63%) sun.security.provider.DigestBase.engineDigest():163 (1 samples, 0.21%) sun.nio.cs.UTF_8$Encoder.encode(char[], int, int, byte[]):632 (2 samples, 0.42%) java.util.LinkedHashMap.get(java.lang.Object):304 (1 samples, 0.21%) sun.security.provider.DigestBase.engineUpdate(byte[], int, int):121 (1 samples, 0.21%) java.lang.AbstractStringBuilder.(init)(int):64 (179 samples, 37.37%) java.lang.AbstractStringB.. java.lang.StringCoding$StringEncoder.encode(char[], int, int):304 (2 samples, 0.42%) java.security.MessageDigest.update(byte[]):335 (11 samples, 2.30%) java.lang.StringCoding.encode(java.lang.String, char[], int, int):344 (2 samples, 0.42%) java.lang.AbstractStringBuilder.(init)(int):64 (8 samples, 1.67%) sun.security.provider.NativePRNG$RandomIO.ensureBufferValid():264 (5 samples, 1.04%) sun.security.provider.NativePRNG$RandomIO.access$200(sun.security.provider.NativePRNG$RandomIO, byte[]):125 (74 samples, 15.45%) sun.secur.. java.lang.String.getBytes():956 (2 samples, 0.42%) sun.security.jca.GetInstance.getInstance(java.lang.String, java.lang.Class, java.lang.String):164 (3 samples, 0.63%) sun.security.provider.DigestBase.engineDigest():165 (41 samples, 8.56%) sun... java.lang.Long.valueOf(long):577 (9 samples, 1.88%) java.security.MessageDigest$Delegate.engineUpdate(byte[], int, int):580 (7 samples, 1.46%) sun.security.jca.GetInstance.getInstance(java.lang.String, java.lang.Class, java.lang.String):157 (2 samples, 0.42%) sun.security.provider.SHA.implCompress(byte[], int):127 (35 samples, 7.31%) sun.. sun.security.provider.NativePRNG$RandomIO.readFully(java.io.InputStream, byte[]):202 (4 samples, 0.84%) sun.misc.IoTrace.fileReadEnd(java.lang.Object, long):-1 (1 samples, 0.21%) java.io.FileInputStream.read(byte[], int, int):274 (1 samples, 0.21%) sun.security.provider.NativePRNG.engineNextBytes(byte[]):114 (74 samples, 15.45%) sun.secur.. sun.security.provider.DigestBase.(init)(java.lang.String, int, int):83 (1 samples, 0.21%) java.lang.Long.toUnsignedString(long, int):242 (13 samples, 2.71%) sun.security.provider.DigestBase.engineReset():156 (1 samples, 0.21%) java.util.HashMap.getEntry(java.lang.Object):462 (1 samples, 0.21%) sun.security.provider.DigestBase.engineReset():156 (1 samples, 0.21%) java.util.UUID.toString():375 (37 samples, 7.72%) jav.. sun.security.provider.MD5.implCompress(byte[], int):146 (2 samples, 0.42%) com.oracle.jrockit.jfr.InstantEvent.commit():135 (1 samples, 0.21%) java.util.LinkedHashMap$Entry.recordAccess(java.util.HashMap):354 (1 samples, 0.21%) java.security.Provider$Service.newInstance(java.lang.Object):1239 (2 samples, 0.42%) java.security.MessageDigest.digest():365 (42 samples, 8.77%) java.. java.util.Random.seedUniquifier():99 (2 samples, 0.42%) sun.security.provider.SHA.implDigest(byte[], int):99 (1 samples, 0.21%) sun.security.provider.SecureRandom.engineNextBytes(byte[]):237 (42 samples, 8.77%) sun... org.wso2.example.JavaThreadCPUUsage.HeavyThread.run():39 (13 samples, 2.71%) com.oracle.jrockit.jfr.DurationEvent.begin():78 (1 samples, 0.21%) org.wso2.example.JavaThreadCPUUsage.HeavyThread.run():28 (298 samples, 62.21%) org.wso2.example.JavaThreadCPUUsage.HeavyThr.. sun.reflect.Reflection.getCallerClass():-1 (1 samples, 0.21%) java.lang.StringBuilder.(init)(java.lang.String):109 (179 samples, 37.37%) java.lang.StringBuilder.(.. java.security.MessageDigest$Delegate.engineDigest():588 (42 samples, 8.77%) java.. java.security.Security.getImpl(java.lang.String, java.lang.String, java.lang.String):695 (6 samples, 1.25%) java.security.MessageDigest.getInstance(java.lang.String):167 (6 samples, 1.25%) sun.security.provider.NativePRNG$RandomIO.implNextBytes(byte[]):285 (3 samples, 0.63%) sun.security.provider.NativePRNG$RandomIO.implNextBytes(byte[]):278 (5 samples, 1.04%) sun.security.provider.SHA.implCompress(byte[], int):122 (3 samples, 0.63%) sun.security.provider.DigestBase.engineUpdate(byte[], int, int):145 (2 samples, 0.42%) java.util.Random.next(int):189 (1 samples, 0.21%) java.lang.Class.getConstructor(java.lang.Class[]):1730 (1 samples, 0.21%) org.wso2.example.JavaThreadCPUUsage.HeavyThread.run():33 (7 samples, 1.46%) com.oracle.jrockit.jfr.TimedEvent.shouldWrite():80 (1 samples, 0.21%) java.security.Provider.getService(java.lang.String, java.lang.String):694 (2 samples, 0.42%) java.lang.Class.getConstructor(java.lang.Class[]):1731 (1 samples, 0.21%) sun.security.provider.SecureRandom.engineNextBytes(byte[]):248 (8 samples, 1.67%) java.lang.Class.arrayContentsEq(java.lang.Object[], java.lang.Object[]):2910 (1 samples, 0.21%) sun.reflect.DelegatingConstructorAccessorImpl.newInstance(java.lang.Object[]):45 (1 samples, 0.21%) sun.security.jca.ProviderList.getService(java.lang.String, java.lang.String):331 (2 samples, 0.42%) java.util.UUID.randomUUID():145 (77 samples, 16.08%) java.util... sun.reflect.GeneratedConstructorAccessor2.newInstance(java.lang.Object[]):-1 (1 samples, 0.21%) sun.security.provider.SHA.implReset():84 (1 samples, 0.21%) sun.misc.IoTrace.fileReadBegin(java.lang.String):-1 (3 samples, 0.63%) java.lang.Number.(init)():49 (1 samples, 0.21%) java.security.MessageDigest.update(byte[]):335 (7 samples, 1.46%) sun.security.provider.DigestBase.engineUpdate(byte[], int, int):139 (11 samples, 2.30%) java.util.LinkedHashMap.get(java.lang.Object):301 (1 samples, 0.21%) java.util.UUID.digits(long, int):385 (29 samples, 6.05%) ja.. java.util.HashMap.hash(java.lang.Object):362 (1 samples, 0.21%)
I got the JFR dump by running a sample application, which consumes more CPU resources. Original source files were obtained from a StackOverflow answer, which explains a way to find a thread consuming high CPU resources. Please note that the package name and line numbers are different in the FlameGraph output when comparing with original source code in StackOverflow Answer. (I will try to share the complete source code later).

I used following JVM arguments:

-XX:+UnlockCommercialFeatures -XX:+FlightRecorder -XX:StartFlightRecording=delay=1s,duration=20s,name=Fixed,filename=/tmp/highcpu.jfr,settings=profile -XX:FlightRecorderOptions=loglevel=info

Then I used following command to generate the FlameGraph

jfr-flame-graph$ ./run.sh -f /tmp/highcpu.jfr -o /tmp/output.txt
FlameGraph$ cat /tmp/output.txt | ./flamegraph.pl --width 550 > ../traces-highcpu.svg


Summary


  • This blog post explains a way to generate CPU Flame Graphs from a Java Flight Recording using a simple Java program.
  • Program is available at GitHub: https://github.com/chrishantha/jfr-flame-graph
  • The program uses the (unsupported) JMC Parser

Update


It's nice to see Srinath's tweet has so many retweets!
Brendon has also mentioned about my program in his Flame Graphs page!
Post a Comment