Java 11 - Flight Recorder (JEP 328)

Troubleshooting, monitoring and profiling are integral parts of the development lifecycle, but some problems occur only in production, under heavy load involving real data.

Flight Recorder is a low overhead (under 1% performance impact) data / event collection framework. Flight Recorder records events originating from applications, the JVM and the OS, and these will be buffered and serialized to a binary format, and then can be consumed for various means, such as troubleshooting. This records can be attached to bug reports and examined by support engineers, allowing after-the-fact analysis of issues in the period leading up to a problem. Tools can use an API to extract information from recording files.

Before Java 11

Before, Java Flight Recorder (JFR) was one of the commercial features.

Java Flight Recorder Commercial License

(Before Java 11) By default, JFR is disabled in the JVM. To enable JFR, you must launch your Java application with the -XX:+FlightRecorder option. Because JFR is a commercial feature, available only in the commercial packages based on Java Platform, Standard Edition (Oracle Java SE Advanced and Oracle Java SE Suite), you also have to enable commercial features using the -XX:+UnlockCommercialFeatures options.

The following example illustrates how to run the MyApp application and immediately start a 60-second recording which will be saved to a file named myrecording.jfr:

$ java -XX:+UnlockCommercialFeatures -XX:+FlightRecorder -XX:StartFlightRecording=duration=60s,filename=myrecording.jfr MyApp

Flight Recorder in Java 11

Through JEP 328, now Java Flight Recorder available (and open source) in Java 11. In following example (JEP328Fibonacci.java), the program writes an event for every Fibonacci number.

JEP328Fibonacci.java

package com.dariawan.jdk11;

import jdk.jfr.Description;
import jdk.jfr.Event;
import jdk.jfr.Label;

@Label("JEP328 Fibonacci")
@Description("Dariawan example: Fibonacci in Flight Recorder")
public class JEP328Fibonacci extends Event {

    @Label("Message")
    String message;

    int fibonacci(int n) {
        if (n <= 1) {
            return n;
        }
        return fibonacci(n - 1) + fibonacci(n - 2);
    }

    public static void main(String args[]) {
        JEP328Fibonacci event = new JEP328Fibonacci();
        for (int n = 1; n < 100; n++) {
            event.message = String.valueOf(event.fibonacci(n));
            event.commit();
        }
    }
}

In Java 11, we are getting the jdk.jfr module. This API allows programmers to produce custom JFR events and consume the JFR events stored in a file to troubleshoot the issue. Using these API, JEP328JFRConsumer will responsible to read and "translate" recording files (which is in binary)

JEP328JFRConsumer.java

package com.dariawan.jdk11;

import java.nio.file.Path;
import java.nio.file.Paths;
import java.util.List;
import jdk.jfr.ValueDescriptor;
import jdk.jfr.consumer.RecordedEvent;
import jdk.jfr.consumer.RecordingFile;

public class JEP328JFRConsumer {

    public static void main(String[] args) throws Exception {
        if (args.length > 0) {
            Path p = Paths.get(args[0]);
            for (RecordedEvent e : RecordingFile.readAllEvents(p)) {
                final List<ValueDescriptor> lvd = e.getFields();
                System.out.println(e.getStartTime());
                for (ValueDescriptor vd : lvd) {
                    System.out.println(vd.getLabel() + "=" + e.getValue(vd.getName()));
                }
                System.out.println("*** <<< *** >>> ***");
            }
        }
    }
}

Let's run JEP328Fibonacci with Flight Recorder using -XX:StartFlightRecording option:

$ java -XX:StartFlightRecording com.dariawan.jdk11.JEP328Fibonacci
Started recording 1. No limit specified, using maxsize=250MB as default.

Use jcmd 13932 JFR.dump name=1 filename=FILEPATH to copy recording data to file.

Then, (at different console) we can dump the events:

$ java com.dariawan.jdk11.JEP328 myRecording.jfr > myRecording.txt

D:\Projects\dallanube\dariawan11\target\classes>jcmd 13932 JFR.dump name=1 filename=fib.jfr
13932:
Dumped recording "1", 961.4 kB written to:

D:\Projects\dariawan-jdk11\target\classes\fib.jfr

If we dump the contents of recording files:

$ java com.dariawan.jdk11.JEP328JFRConsumer fib.jfr > fib.txt

When we scan through file fib.txt, there are many records, but one of the event is looks like this:

*** fib.txt truncated ***
...
2019-02-12T15:59:59.236512274Z
Start Time=3220081164
Duration=0
Event Thread={
  osName = "main"
  osThreadId = 16108
  javaName = "main"
  javaThreadId = 1
  group = {
    parent = {
      parent = null
      name = "system"
    }
    name = "main"
  }
}

Stack Trace=null
Event Id=1933
Setting Name=enabled
Setting Value=true
*** <<< *** >>> ***
2019-02-12T15:59:59.236700514Z
Start Time=3220514116
Duration=0
Event Thread={
  osName = "main"
  osThreadId = 16108
  javaName = "main"
  javaThreadId = 1
  group = {
    parent = {
      parent = null
      name = "system"
    }
    name = "main"
  }
}

Stack Trace={
  truncated = false
  frames = [
    {
      method = {
        type = {
          classLoader = {
            type = {
              classLoader = {
                type = null
                name = "bootstrap"
              }
              name = "jdk/internal/loader/ClassLoaders$AppClassLoader"
              package = {
                name = "jdk/internal/loader"
                module = {
                  name = "java.base"
                  version = "11.0.1"
                  location = "jrt:/java.base"
                  classLoader = {
                    type = null
                    name = "bootstrap"
                  }
                }
                exported = true
              }
              modifiers = 32
            }
            name = "app"
          }
          name = "com/dariawan/jdk11/JEP328Fibonacci"
          package = {
            name = "com/dariawan/jdk11"
            module = null
            exported = true
          }
          modifiers = 33
        }
        name = "main"
        descriptor = "([Ljava/lang/String;)V"
        modifiers = 9
        hidden = false
      }
      lineNumber = 25
      bytecodeIndex = 29
      type = "Interpreted"
    }
  ]
}

Message=1
*** <<< *** >>> ***
...
*** fib.txt truncated ***

Some JVM arguments to enable JFR

Continuous With Dump on Demand

$ java -XX:StartFlightRecording=settings=default com.dariawan.jdk11.JEP328Fibonacci
Started recording 1. No limit specified, using maxsize=250MB as default.

Use jcmd 9024 JFR.dump name=1 filename=FILEPATH to copy recording data to file.

Is what we do in sample JEP328Fibonacci above

settings=path

Specifies the path and name of the event settings file (of type JFC). By default, the default.jfc file is used, which is located in JRE_HOME/lib/jfr. This default settings file collects a predefined set of information with low overhead, so it has minimal impact on performance and can be used with recordings that run continuously.

A second settings file is also provided, profile.jfc, which provides more data than the default configuration, but can have more overhead and impact performance. Use this configuration for short periods of time when more information is needed.

Time-Based

$ java -XX:StartFlightRecording=delay=20s,duration=60s,filename=d:\fib.jfr,settings=default,name=Fibonacci com.dariawan.jdk11.JEP328Fibonacci
Recording 1 scheduled to start in 20 s. The result will be written to:

d:\fib.jfr

Airplane Under Blue Sky

delay=time

Specifies the delay between the Java application launch time and the start of the recording. Append s to specify the time in seconds, mfor minutes, h for hours, and d for days. For example, specifying 10m means 10 minutes. By default, there’s no delay, and this parameter is set to 0.

duration=time

Specifies the duration of the recording. Append s to specify the time in seconds, m for minutes, h for hours, and d for days. For example, specifying 5h means 5 hours. By default, the duration isn’t limited, and this parameter is set to 0.

filename=path

Specifies the path and name of the file to which the recording is written when the recording is stopped, for example:

recording.jfr
/home/user/recordings/recording.jfr
c:\recordings\recording.jfr

name=identifier

Takes both the name and the identifier of a recording.

Continuous With Dump on Exit

$ java -XX:StartFlightRecording=settings=default,dumponexit=true,filename=D:\dump.jfr com.dariawan.jdk11.JEP328Fibonacci
Started recording 1. No limit specified, using maxsize=250MB as default.

Use jcmd 13484 JFR.dump name=1 to copy recording data to file.

dumponexit={true|false}

Specifies if the running recording is dumped when the JVM shuts down. If enabled and a filename is not entered, the recording is written to a file in the directory where the process was started. The file name is a system-generated name that contains the process ID, recording ID, and current timestamp, similar to hotspot-pid-47496-id-1-2018_01_25_19_10_41.jfr. By default, this parameter is disabled.

Conclusion

Java Flight Recording now made available with Java 11, and with modules API, programmers now can customize these "data" to their comfort level. I don't think this is will reduce the needs of using third party profilers (Let's the pro done and deliver their job), but at least it's removes "some level" dependency for those tools.

This article is part of Java 11 Features and Changes Series.

Java 11 - Remove the Java EE and CORBA Modules (JEP 320)

Desson Ariawan