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!

Comments

Post a Comment

Popular posts from this blog

Monitor WSO2 Carbon logs with Logstash

Image
The ELK stack  is a popular stack for searching and analyzing data. Many people use it for analyzing logs. WSO2 also has a full-fledged Big Data Analytics Platform, which can analyze logs and do many more things. In this blog post, I'm explaining on how to monitor logs with  Elasticsearch , Logstash and Kibana . I will mainly explain logstash configurations. I will not show how to set up Elasticsearch and Kibana. Those are very easy to setup and there are not much configurations. You can just figure it out very easily! :) If you want to test an elasticsearch server, you can just extract the elasticsearch distribution and start an elasticsearch server. If you are using Kibana 3, you need to use a web server to host the Kibana application. With Kibana 4, you can use the standalone server provided in the distribution. Configuring Logstash Logstash  is a great tool for managing events and logs. See  Getting Started with Logstash  if you haven't used ...
Read more

Java Ergonomics and JVM Flags

Java Virtual Machine can tune itself depending on the environment and this smart tuning is referred to as Ergonomics . When tuning Java , it's important to know which values were used as default for Garbage collector, Heap Sizes, Runtime Compiler by Java Ergonomics There are many JVM command line flags. So, how do we find out which JVM flags are used? It turns out that JVM has flags to print flags. :) I tested following commands with Java 8. $ lsb_release -a No LSB modules are available. Distributor ID: Ubuntu Description: Ubuntu 15.04 Release: 15.04 Codename: vivid $ uname -a Linux isurup-ThinkPad-T530 3.19.0-26-generic #28-Ubuntu SMP Tue Aug 11 14:16:32 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux Printing Command Line Flags We can use "-XX:+PrintCommandLineFlags" to print the command line flags used by the JVM. This is a useful flag to see the values selected by Java Ergonomics. $ java -XX:+PrintCommandLineFlags -version -XX:InitialHeapSize=...
Read more

Java CPU Flame Graphs

Update (September 14, 2015): Java 8 Update 60 was released on August 18, 2015. There are some recent changes to "perf-map-agent". There is no longer a script named "perf-java" and you should use "bin/create-java-perf-map.sh " Brendan Gregg shared an exciting news in his Monitorama talk: The " JDK-8068945 " is fixed in Java 8 Update 60 Build 19 ! Without this fix, it was not possible to see full stack in Java with Linux perf_events and standard JDK (without any patches). For more information, see Brendan's Java CPU Flame Graphs page. The Problem with Java and Perf First of all, let's see what's the problem with using current latest Java and perf. For this example, I used the same program explained in my previous blog post regarding FlameGraphs . java org.wso2.example.JavaThreadCPUUsage.App Then I sampled on-CPU functions for Java program using perf. (See Brendan's Perf Examples ) sudo perf record -F 99 -g -...
Read more