Skip to main content

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 Zoomorg.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():745sun.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!

Comments

Popular posts from this blog

Finding how many processors

I wanted to find out the processor details in my laptop and I found out that there are several ways to check. For example, see The RedHat community discussion on  Figuring out CPUs and Sockets . In this blog post, I'm listing few commands to find out details about CPUs. I'm using Ubuntu in my Lenovo ThinkPad T530 laptop and following commands should be working any Linux system. Display information about CPU architecture $ lscpu Architecture: x86_64 CPU op-mode(s): 32-bit, 64-bit Byte Order: Little Endian CPU(s): 4 On-line CPU(s) list: 0-3 Thread(s) per core: 2 Core(s) per socket: 2 Socket(s): 1 NUMA node(s): 1 Vendor ID: GenuineIntel CPU family: 6 Model: 58 Model name: Intel(R) Core(TM) i7-3520M CPU @ 2.90GHz Stepping: 9 CPU MHz: 1199.988 CPU max MHz: 3600.0000 CPU min MHz: 1200.0000 BogoMIPS: 5787.1...

Java Mission Control & Java Flight Recorder

Last year, I got two opportunities to talk about Java Mission Control & Java Flight Recorder. I first talked about " Using Java Mission Control & Java Flight Recorder " as an internal tech talk at WSO2 . I must thank Srinath for giving me that opportunity. After that, Prabath also invited me to do a talk at Java Colombo Meetup . Prabath, Thank you for inviting me and giving me the opportunity to talk at the Java Colombo Meetup! I'm also very excited to see that Marcus Hirt , the Team Lead for Java Mission Control has mentioned about the Java Colombo Meetup in his blog post: " My Favourite JMC Quotes ". It's so nice to see "Sri Lanka" was mentioned in his blog post! :) From Marcus' Blog Here are the slides used at the meetup. Java Colombo Meetup: Java Mission Control & Java Flight Recorder from Isuru Perera Marcus Hirt's blog posts really helped me to understand JMC & JFR concepts and his tutorials were very helpful...