Using Java Flight Recorder

Java Flight Recorder is a profiling and event collection framework built right into the Oracle JDK.

With Java Mission Control, you can start a Java Flight Recording and analyze the recording in detail. The Java Flight Recorder (JFR) gathers low-level information and it helps to understand the behavior of the Java Application and the Java Virtual Machine (JVM).

Most interesting thing about JFR is that it has very low overhead on Java Application and therefore the JFR can be even run in production environments. The overhead is very low as the JFR collects events within the JVM itself. Other profilers use the standard JVM Tool Interface.

The JFR requires a commercial license if you are planning to run it in production. The main reason is that JFR is a “Commercial Feature” in the JDK. However, it’s free to use in development.

What is Java Mission Control (JMC)?

Java Mission Control is an advanced set of tools that enables efficient and detailed analysis of the extensive data collected by Java Flight Recorder.

JMC was first included in the Oracle JDK 7 Update 40 (7u40). Earlier the “Mission Control” was a part of JRockit JDK. As mentioned above, the JMC is a commercial feature in Oracle JDK. JMC enables you to monitor and manage Java applications. It’s important to note that the JMC is a desktop application, which runs on top of Eclipse.

The JMC has a “JVM Browser”, which shows the running Java Applications. If the Java application is running on a remote machine, you can create a new “JVM Connection” and connect via JMX. After having a “JVM Connection”, you can either open the “JMX Console” or start a Java Flight Recording.

Please make sure to check the JMC help using Help -> Java Mission Control Help.

The JMC help is really useful to understand each “Tab Groups” and “Tabs” in the Java Mission Control’s Interface.

Unfortunately, the help page is not working if you are using a JDK with the version above 8u77. The latest JDK available now is JDK 8u112 and the help is not working in that version as well.

JMX Console

The JMX Console connects to the JVM and monitors in real-time. As the name suggests, it collects data via the Java Management Extensions (JMX).

With JMX Console, you can create rules, which will trigger some actions based on some conditions. For example, it can start a Java Flight Recording when the CPU usage of the JVM process is over 90%.

How to enable Java Flight Recorder?

There are few ways to enable the JFR. Since JFR is a commercial feature, you must unlock commercial features before trying to run JFR.

So, you need to have following flags.

java -XX:+UnlockCommercialFeatures -XX:+FlightRecorder

If you are using Java 8 update 40 (8u40) or later, you can now dynamically enable JFR. So, you don’t need to have above arguments if you need to run JFR. This really helps if you are seeing a problem and there is no need to restart the server. Sometimes a restart solves the problem anyway. :) But that’s just temporary and it’s always good to analyze the root cause of the problem.

JMC 5.5 also gives you the ability to dynamically enable JFR when you are going to start a flight recording from the UI.

So, with the dynamic enabling feature, you no longer have to specify -XX:+UnlockCommercialFeatures and -XX:+FlightRecorder flags when starting the Java application to create a Java Flight Recording. Later you will see how you can start a Java Flight Recording by dynamically enabling the JFR.

Improving the accuracy of JFR Method Profiler

An important feature of JFR Method Profiler is that it does not require threads to be at safe points in order for stacks to be sampled. Generally, the stacks will only be walked at safe points. HotSpot JVM doesn’t provide metadata for non-safe point parts of the code.

You can use following flags to improve the accuracy.

-XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints

When you specify these arguments, the JFR can get metadata for non-safe points as well.

Types of Recordings

Before running the JFR, let’s understand the types of recordings available in JFR. There are two types recordings.

1. Time Fixed Recordings
2. Continuous Recordings

In Time Fixed Recordings, JFR will collect events for a fixed duration and then it will dump the recording to the specified file. If the recording was starting in JMC, the recording will be opened automatically.

A Time Fixed Recording can be used to profile the Java application for a given duration.

Continuous Recordings do not have an end time. Since the recording is running continuously, you must explicitly dump the recording. It’s important to know that the JFR collects events and write data to a global buffer. When this global buffer fills up, the oldest data are discarded. Therefore when you request a dump, you will get the data currently available in the buffer. You can specify the maximum allowed size of data to keep on disk and the maximum allowed age of events.

A Continuous Recording is very useful to keep it running and get a Flight Recording dump only when you see an issue.

JFR Event Settings

When you want to start a Flight Recording, you can give a settings configuration, which specifies the enabled events and thresholds for some events.

There are two event settings by default in Oracle JDK and those are located in $JAVA_HOME/jre/lib/jfr

• Continuous — default.jfc
• Profiling — profile.jfc

As you can see, “default.jfc” is the default events configuration.

The default setting has low overhead and it’s primarily used for Continuous Recordings.

The profile setting gathers more data. You can start a Time Fixed Recording with profile setting to get more events and troubleshoot a performance issue. When you enable more events, the performance overhead will also increase.

It is important to note that you can run multiple recordings concurrently and have different settings for each recording. However, the JFR runtime will use same buffers and resulting recording contains the union of all events for all recordings active at that particular time. This means that you might get more than you asked for, but not less.

Running Java Flight Recorder

There are few ways we can run JFR. For all the examples mentioned below, the sample “highcpu” program is used. The code is available at https://github.com/chrishantha/sample-java-programs/releases/tag/v0.0.1

• Using the JFR plugin in JMC
• Using the command line
• Using the Diagnostic Command

Running JFR from JMC

You can use the Flight Recorder plug-in integrated into JMC to produce a Java Flight Recording. The GUI is very intuitive and you can follow the steps mentioned below in the JMC.

• Right click on JVM and select “Start Flight Recording”. If it’s a remote JVM, you will have to create a “JVM Connection” first.
• Select the type of recording: Time fixed / Continuous
• Select the “Event Settings” template
• Modify the event options for the selected flight recording template (Optional)
• Modify the event details (Optional)

Running JFR from Command Line

In this section, let’s see how you can start a profiling recording and a continuous recording using command line options.

Please see “Advanced Runtime Options” for more information about all options mentioned in this section.

Starting a Profiling Recording

A “Profiling Recording” is a Time Fixed Recording with profile setting.

To produce a Time Fixed Recording from the command line, you can use “- XX:StartFlightRecording” option.

For example:

-XX:StartFlightRecording=delay=20s,duration=60s,name=Test,filename=recording.jfr,settings=profile

Let’s see how to use in “highcpu” sample program. Remember, you need to unlock commercial features and enable the Flight Recorder. You can also enable the non-safepoints debug flag.

Following example shows how to start a Profiling Recording for 60 seconds after 20 seconds of starting the JVM.

sample-java-programs/highcpu$ java -XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints -XX:+UnlockCommercialFeatures -XX:+FlightRecorder -XX:StartFlightRecording=delay=20s,duration=60s,name=Test,filename=recording.jfr,settings=profile -jar target/highcpu-0.0.1.jar

As mentioned previously, the setting file is available in $JAVA_HOME/jre/lib/jfr. You can also specify a path if you have a custom settings file. If you want to create a custom settings file and modify the events configuration, please check the blog post on “Specifying a custom Event Settings file for Java Flight Recorder”

If you need to see more Flight Recorder logs, you can use following option to change log level

-XX:FlightRecorderOptions=loglevel=info

Following is the output when running with above option.

sample-java-programs/highcpu$ java -XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints -XX:+UnlockCommercialFeatures -XX:+FlightRecorder -XX:StartFlightRecording=delay=20s,duration=60s,name=Test,filename=recording.jfr,settings=profile -XX:FlightRecorderOptions=loglevel=info -jar target/highcpu-0.0.1.jar 
[jfr][INFO ][0.000] JFR log level set. Log level now at [INFO ]
[jfr][INFO ][0.085] Using /tmp/2016_11_30_14_07_03_490 as Flight Recorder repository.
Recording 1 scheduled to start in 20 s. The result will be written to:
/home/isuru/work/git-projects/sample-java-programs/highcpu/recording.jfr
App [runHashing=true, runSleeping=true, runMath=true, hashingWorkers=6, sleepingWorkers=4, mathWorkers=2, hashDataLength=2000, hashingAlgorithm=SHA-1, exitTimeoutInSeconds=120]
Starting Application...
[jfr][INFO ][20.635] Starting recording [id=1, name=Test, destination=recording.jfr, start=Wed Nov 30 14:07:23 IST 2016, duration=60000ms]
[jfr][INFO ][82.069] Copied 134274993 bytes (before compression) to recording.jfr in 11 chunks
[jfr][INFO ][82.069] Stopped recording [id=1, name=Test, destination=recording.jfr, start=Wed Nov 30 14:07:23 IST 2016, end=Wed Nov 30 14:08:23 IST 2016, duration=60000ms]
Exiting now...
[jfr][INFO ][120.775] Flight Recorder repository deleted

In above output, you can see that JFR is using a temporary directory called “repository”. JFR use that directory to save the recording temporarily in the disk.

Starting a Continuous Recording

You can start a Continuous Recording from the command line using “-XX:FlightRecorderOptions=defaultrecording=true”. This is also called “The Default Recording”

As mentioned previously, you can start a Continuous Recording that can later be dumped only if needed.

When you want to run a continuous recording, you have two options to limit the amount of data you need.

1. Set the maximum size (in bytes) of disk data to keep for the default recording using the maxsize parameter.
2. Set the maximum age of disk data to keep for the default recording using the maxage parameter.

Above two parameters are value only if you set the disk=true parameter.

Please keep in mind that the thresholds are checked only when a new recording chunk is created. You can specify the recording chunk size using maxchunksize parameter. The default value is 12MB. Since the default recording doesn’t have lot of events, it might take a considerable time to fill the data and trigger removal of chunks. For example, if you use maxage=10m, you might get events for around 40 minutes to 1 hour.

See the following example to start a continuous recording with 2 hours of data. The temporary data will be stored in the disk.

-XX:FlightRecorderOptions=defaultrecording=true,disk=true,repository=/tmp,maxage=2h

Let’s use above options with the sample program.

sample-java-programs/highcpu$ java -XX:+UnlockCommercialFeatures -XX:+FlightRecorder -XX:FlightRecorderOptions=defaultrecording=true,disk=true,repository=/tmp,maxage=2h -jar target/highcpu-0.0.1.jar

In order to get a dump from a continuous recording, you need to manually dump using JMC or diagnostic command. You can refer next section to see how diagnostic commands are used.

When you want to dump the recording, you need to specify a new location. The files in the repository are only temporary.

When you enable the default recording, you can also get a dump on exit.

You can use following options to get a flight recording when the program exits.

-XX:FlightRecorderOptions=defaultrecording=true,dumponexit=true,dumponexitpath=/tmp/dumponexit.jfr

Please note that only the default recording can be used with the dumponexit and dumponexitpath parameters

Example:

sample-java-programs/highcpu$ java -XX:+UnlockCommercialFeatures -XX:+FlightRecorder -XX:FlightRecorderOptions=defaultrecording=true,disk=true,repository=/tmp,maxage=2h,dumponexit=true,dumponexitpath=/tmp/dumponexit.jfr,loglevel=info -jar target/highcpu-0.0.1.jar — exit-timeout 10
[jfr][INFO ][0.000] JFR log level set. Log level now at [INFO ]
[jfr][INFO ][0.047] Using /tmp/2016_11_30_14_20_51_983 as Flight Recorder repository.
[jfr][INFO ][0.455] Starting recording [id=0, name=HotSpot default, start=Wed Nov 30 14:20:51 IST 2016, maxAge=7200000ms]
App [runHashing=true, runSleeping=true, runMath=true, hashingWorkers=6, sleepingWorkers=4, mathWorkers=2, hashDataLength=2000, hashingAlgorithm=SHA-1, exitTimeoutInSeconds=10]
Starting Application…
Exiting now…
[jfr][INFO ][10.547] Dump on exit: recording 0 ‘HotSpot default’
[jfr][INFO ][10.563] Starting recording [id=1, name=dump-on-exit-clone-of-0, start=Wed Nov 30 14:20:51 IST 2016]
[jfr][INFO ][10.645] Stopped recording [id=1, name=dump-on-exit-clone-of-0, start=Wed Nov 30 14:20:51 IST 2016, end=Wed Nov 30 14:21:01 IST 2016]
[jfr][INFO ][10.665] Copied 673595 bytes (before compression) to /tmp/dumponexit.jfr in 2 chunks
[jfr][INFO ][10.685] Stopped recording [id=0, name=HotSpot default, start=Wed Nov 30 14:20:51 IST 2016, end=Wed Nov 30 14:21:02 IST 2016, maxAge=7200000ms]
[jfr][INFO ][10.686] Flight Recorder repository deleted

Running JFR using Diagnostic Commands

The “jcmd” utility in JDK can be used to send diagnostic command request to the JVM. With jcmd, you can control Java Flight Recordings.

For more details on jcmd syntax and other usage details, see the jcmd command man page.

When you just run jcmd, you will see a list of java processes running in the system.

Let’s run the sample program as follows.

java -jar target/highcpu-0.0.1.jar --hashing-workers 1 --math-workers 1 --sleeping-workers 1 --exit-timeout 0

Following is the output of jcmd.

$ jcmd
3586 target/highcpu-0.0.1.jar --hashing-workers 1 --math-workers 1 --sleeping-workers 1 --exit-timeout 0
3619 sun.tools.jcmd.JCmd

To send diagnostic command requests to the JVM, you can use following syntax.

jcmd <process id/main class> <command> [options]

The help command shows all available commands.

$ jcmd highcpu help 
3586:
The following commands are available:
JFR.stop
JFR.start
JFR.dump
JFR.check
VM.native_memory
VM.check_commercial_features
VM.unlock_commercial_features
ManagementAgent.stop
ManagementAgent.start_local
ManagementAgent.start
GC.rotate_log
Thread.print
GC.class_stats
GC.class_histogram
GC.heap_dump
GC.run_finalization
GC.run
VM.uptime
VM.flags
VM.system_properties
VM.command_line
VM.version
help
For more information about a specific command use 'help <command>'.

Dynamically Enabling JFR from diagnostic commands

With diagnostic commands, you can dynamically enable flight recorder.

You can use VM.check_commercial_feature command to check whether commercial features are unlocked.

$ jcmd highcpu VM.check_commercial_features
3586:
Commercial Features are locked.

With VM.unlock_commercial_features command, you can unlock commercial features.

See following example for unlocking commercial features.

$ jcmd highcpu VM.unlock_commercial_features
3586:
Commercial Features now unlocked.

If you run the same command again, it will say that commercial features are already unlocked.

When you run the VM.check_commercial_features command again, it will show the status of individual features.

$ jcmd highcpu VM.check_commercial_features
3586:
Commercial Features are unlocked.
Status of individual features:
 Java Flight Recorder has not been used.
 Resource Management is disabled.
 Current Memory Restriction: None (0)

Now you can use the JFR.start diagnostic command to enable the Flight Recorder.

Starting a recording with diagnostic commands

See the following example for starting a Profiling Recording.

jcmd highcpu JFR.start settings=profile delay=20s duration=60s name=Test filename=recording.jfr

For more information about options, try the following command.

jcmd highcpu help JFR.start

You can use JFR.check command to check running Java Flight Recordings.

For example:

$ jcmd highcpu JFR.check 
3586:
Recording: recording=1 name="Test" duration=1m filename="recording.jfr" compress=false (running)

If you want to start a Continuous Recording, you can use following command.

jcmd highcpu JFR.start defaultrecording=true

Following is the output of above command.

3586:
Started recording "HotSpot default"
Use JFR.dump recording=0 filename=FILEPATH to copy recording data to file.

When you start a “Default Recording”, the JFR will use “HotSpot default” as the name and its recording number will be always zero.

Dumping Flight Recordings

You can use JFR.dump command to get a JFR dump

See the following example to get a dump from default recording.

jcmd highcpu JFR.dump recording=0 filename=default.jfr

When dumping, you can either specify the recording number or the recording name.

It seems that spaces are not allowed for the recording name when using diagnostic commands. So, you will not be able to get a dump from the default recording using the name. However, if you start any other recording with a name, you can get a dump using the name.

For example, let’s start a Profiling Recording for two hours.

jcmd highcpu JFR.start settings=profile duration=2h name=Profiling

You can get a dump whenever you want.

jcmd highcpu JFR.dump name=Profiling filename=profiling.jfr

Stopping a recording

You can also stop a running recording using JFR.stop command.

For example:

jcmd highcpu JFR.stop name=Profiling

If you want, you can also stop the default recording.

jcmd highcpu JFR.stop recording=0

Analyzing Flight Recordings

JFR runtime engine dumps recorded data to files with *.jfr extension. These binary files can be viewed from JMC.

There are tab groups showing certain aspects of the JVM and the Java application runtime such as Memory, Threads, I/O etc.

JFR Tab Groups

• General: Details of the JVM, the system, and the recording.
• Memory: Information about memory & garbage collection.
• Code: Information about methods, exceptions, compilations, and class loading.
• Threads: Information about threads and locks.
• I/O: Information about file and socket I/O.
• System: Information about environment
• Events: Information about the event types in the recording

I’m planning to write another article on how to analyze Flight Recordings.

You can also read Java Platform, Standard Edition Troubleshooting Guide, which has more details on using Java Flight Recorder.

You can also try the jfr-flame-graph project, which can be used to generate Flame Graphs using the Method Profiling Samples from the Java Flight Recorder dump. Using a Flame Graph, you can easily analyze the “Call Tree”.