Java Mission Control & Flight Recorder

• 1: Introduction
• 2: Method Profiling
• 3: Exceptions
• 4: Threads
• 5: Memory
• 6: I/O Operations
• 7: References

1 - Introduction

Java Flight Recorder

The Java Flight Recorder (JFR) is a very low overhead profiling and diagnostics tool. It was inherited from the JRockit JVM, and originally was offered as part of the HotSpot JVM. It is designed to be “black box” data recorder of the the run-time, which can be used in production environments, making it an attractive tool for profiling code since it has low overhead on the JVM.

Newer versions of JMC are developed as part of the OpenJDK Mission Control project.

To enable the Flight Recorder on the JVM, the following options need to be included on the JVM:

-XX:+UnlockCommercialFeatures -XX:+FlightRecorder

❗ Notice that you have to include -XX:+UnlockCommercialFeatures first in the options listing. This is because using Flight Recorder is a feature that requires additional licensing when used in production environments. One of the following licenses is required in order to utilize this in a production environment.

• Oracle Java SE Advanced
• Oracle Java SE Suite

However, you may use this in non-production environments without additional licensing.

Higher Fidelity on Method Profiling

To get better fidelity on method profiling, include the following options which will enable the compiler to include additional metadata on non-safe code points. This is helpful, as sometimes the metadata will not fully resolve to the correct line in the code.

-XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints

Java Mission Control

We will be using Java Mission Control to monitor and evaluate the Java flight recordings. To start up Java Mission Control, simply executing the following in your console:

jmc

💡 In order to be able to invoke jmc (Java Mission Control) from your console, it assumes $JAVA_HOME/bin is on your $PATH. If it is not included, go ahead and update your profile to include this so you can easily invoke jmc from your terminal.

Start Service with JFR

Let’s start profiling our service. Start the service up by enabling JFR:

Start from the console

# Note, if you are running this server from a different folder, consider changing the SERVER_HOME
SERVER_HOME=java-perf-workshop-server/target
java -XX:+UnlockCommercialFeatures -XX:+FlightRecorder -XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints -jar $SERVER_HOME/java-perf-workshop-server-1.1.0-SNAPSHOT.jar server server.yml

💡 Starting with Java Mission Control 5.5 (included in Oracle Java 8u40), you no longer have to enable JFR prior to capturing the recording (it will dynamically enable it, after prompting about it).

Start Flight Recording from JMC

This will open a window where you apply some settings for the recording. First select that you want this to be a Continuous recording and for Event settings, we will import a template to get some consistent settings for profiling. Within the Template Manager, select Import Files… and import the open_jdk_9_.jfc included in the content/docs/jmc folder. It should appear as Java Performance Workshop JDK9+ Profile. Select this as the Event Settings and then click on Finish.

For reference, these are the options for the template.

First select that you want this to be a Continuous recording and for Event settings we will use Profiling on Server.

Once your flight recording is being captured in a Continuous recording, it will show a ∞.

💡 You can see the JFR templates (continuous / profile) which are shipped as part of the JRE in: $JAVA_HOME/jre/lib/jfr. These become helpful if you are wanting to compare your settings to some of the standard ones.

Generate HTTP traffic on service

We will want to generate some traffic on the service to measure some general characteristics of the service:

• Throughput (requests per second)
• Response time
• Trend of response time over time

By generating traffic on service, this gives us baseline activity in the JVM to start evaluating the flight recording.

Basic test

This service under test, is a simple web service which provides results based on a search API. When interacting with the service, you can simply supply a HTTP GET on the search resource with a query parameter (‘q’) with the term that you are searching for. It will then return KCDC’s 2015 sessions that contain that term. Example:

curl "http://localhost:8080/search?q=jvm"
{
  "results" : [ {
    "title" : "Concurrency Options on the JVM",
    "presenter" : "Jessica Kerr",
    "sessionType" : "Regular Session"
  }, {
    "title" : "Exploring the Actor Model with Akka.NET",
    "presenter" : "Robert Macdonald Smith",
    "sessionType" : "Regular Session"
  }, {
    "title" : "What's in your JVM?",
    "presenter" : "Carl Chesser",
    "sessionType" : "4-Hour Workshop"
  } ]
}

Using Apache Benchmark

We can utilize Apache Benchmark to generate traffic on the service From the console, we will execute the following to generate traffic against our service. Note, we will use a very basic search of just “a”, since this will generate more results.

ab -n 1000 -c 15 "http://localhost:8080/search?q=a"

Using loadtest

An alternative to Apache Benchmark, is loadtest (a node.js equivalent). To install:

sudo npm install -g loadtest

Then you can execute similarly:

loadtest -n 1000 -c 15 "http://localhost:8080/search?q=a"

Using gatling

Alternatively, you can use gatling (a performance library with a scala dsl ).

This should launch the WorkshopSimulation.

 mvn -f java-perf-workshop-tester/ gatling:test

Sample output while running:

[~/java-perf-workshop/java-perf-workshop-tester]$ mvn gatling:test
[INFO] Scanning for projects...
[INFO]
[INFO] ------------------------------------------------------------------------
[INFO] Building java-perf-workshop-tester 1.1.0-SNAPSHOT
[INFO] ------------------------------------------------------------------------
[INFO]
[INFO] --- gatling-maven-plugin:2.2.4:test (default-cli) @ java-perf-workshop-tester ---
19:12:16,662 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
19:12:16,663 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
19:12:16,663 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/J:/Workspaces/java-perf-workshop/java-perf-workshop-tester/target/test-classes/logback.xml]
19:12:16,663 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs multiple times on the classpath.
19:12:16,663 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [file:/J:/Workspaces/java-perf-workshop/java-perf-workshop-tester/target/test-classes/logback.xml]
19:12:16,663 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [jar:file:/C:/Users/JMonterrubio/.m2/repository/io/gatling/gatling-maven-plugin/2.2.4/gatling-maven-plugin-2.2.4.jar!/logback.xml]
19:12:16,727 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
19:12:16,731 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
19:12:16,737 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [CONSOLE]
19:12:16,742 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
19:12:16,781 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to WARN
19:12:16,782 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [CONSOLE] to Logger[ROOT]
19:12:16,782 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
19:12:16,783 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@7a0ac6e3 - Registering current configuration as safe fallback point

Simulation cchesser.javaperf.workshop.WorkshopSimulation started...

Stop Flight Recorder

After you have played traffic through the service, you can then stop your flight recording from JMC.

Then dump the whole recording.

The Flight Recording

From a Java Flight Recording, there are several categories of information (pages) you can view from JMC:

• Code Information:
  • Method Profiling: Provides information about specific method runs and how long each run took, identifying hot spots in your code base.
  • Exceptions: Displays Exceptions and Errors thrown and which methods threw them. Viewing exceptions requires editing the settings to also capture Exceptions.
• Thread information:
  • Threads: Provides a snapshot of all the threads that belong to the Java Application and the thread activity.
  • Lock Instances: Provides further details on threads by specifying lock information, showing which threads request and which threads take a particular lock.
  • Thread Dump: Provides period thread dump information.
• Memory Information:
  • Memory: Represents heap memory usage of the JVM.
• IO Information:
  • File I/O: Displays File costs and behaviors
  • Socket I/O: Displays Network costs and behaviors
• JVM Internals:
  • Garbage Collections: Displays heap usage compared to pause times as well as GC events.
  • Compilations: Provides details on code compilation.
  • TLAB Allocations: Displays Thread Local Allocation Buffers.
• System Information:
  • Processes: See other processes on the system and what is competing for resources.
  • Environment: Provides information about the environment in which the recording was made.
  • System Properties: Show properties passed on to the JVM.
• Events: Event Browser: View detailed log of the events within the JVM. You can use this page to further filter down on events across all the pages in the recording.

2 - Method Profiling

Our first look at the recording will start with finding out where we might be spending time with our code.

Method Profiling Page

We’ll start by taking a look at the detailed Method Profiling Page. This page displays how often a specific method is ran based on sampling.

By default, this view groups threads by method, but you can also include the line number for each method. This can be accomplished by selecting the View Menu option and going to Distinguish Frames By and selecting Line Number.

💡 Generally, you don’t need this, as it can be quite apparent by the base method being invoked where the cost is at. Though, it may be helpful to include in some contexts.

Java Application

Navigate to the Java Application page. This page provides an overview of the state of the JVM and collates information from a couple of the dedicated pages.

Using the checkboxes on the right of the Graph, select only Method Profiling to narrow down the set of events on the graph:

The Stack Trace view from this page can give you a better count of sampled methods (not just the ones from a specific Method Profiling event)

This information is the equivalent of the Hot Methods tab in JMC 5, see forum discussion.

We can then use this information to correlate what is happening in our code:

Explore

• Walk around to look at other areas where you are spending time in your code.
  • In many cases you find that there are very expensive areas of code that you cannot change (as you may not own it), but you can dictate whether or not it should be executed (or executed as frequently).

Follow Ups

• Is there any method that stands out to you that might be unnecessarily called?

3 - Exceptions

In this section we’ll dive into the Exceptions page and find out what information we can learn from it. Start by selecting the Exceptions page from the Outline.

This page offers the following sections:

• Overview: You can get Exceptions by Class and Count
• Message: View the detail messages for all exceptions and errors.
• Timeline/Event Log: View when a particular exception was thrown.
• StackTrace: Identify where the exception was thrown from.

.

You can select an exception from the table to filter the information to that particular exception. You could also filter by a particular exception message.

Explore

NullPointerExceptions are a familiar exception you deal with in Java, and often times indicate a programming error. Other exception types often point to a common symptom.

Follow Ups

• What are the exceptions that are getting generated the most?
  • What stack traces are the contributor?
• Can you find any areas in our code where we may have made an incorrect assumption regarding nullability?
  • Are there any other areas in our code where we might have made an incorrect assumption based on an exception’s class?
• Are there any exceptions that might indicate a problem with our dependencies?

4 - Threads

The Threads page provides a snapshot of all threads in our application, and we can use it to acquire information about computation and latency events.

Thread Chart

We can use the Thread Chart view to select a region of time and view the state of threads and the most common stack frames for that particular time slice:

We can also edit the types of events shown by the chart. Right click on the chart, and select Edit Thread Activity Lanes

We can then narrow down on specific events.

For the purpose of this section filter on only the Sleep events. Then, select a period of time and look at what has caused our threads to go to sleep for that particular period:

Once you’re done with the filtered view, right click on the Thread page and Reset the page (to return to the default state).

By Thread

We can select an individual thread from the Thread Table to further filter the data just for that thread. From this filtered view, we can inspect what the commonly executed methods are for a particular thread.

We can then use the stacktrace view to correlate what piece of code executed the most.

Explore

There’s a couple of threads specifically created by our application, these are the wkshp-conf-loader named threads. The dw-* named threads are threads created by DropWizard to handle specific requests (you might have noticed this based on the name containing a REST Resource). Explore the state of some of these threads while thinking about the follow up questions.

Follow Ups

• Where are we spending most of our time sleeping? What is causing this?
• Are there any unnecessary method invocations? Are any threads doing work that isn’t visible?

5 - Memory

The memory page shows us the overall memory usage and garbage collection events for our recording.

The Class Table lets us view the total memory allocation dedicated to particular instances of that class. Selecting a particular class will allow us to view what code paths are responsible for creating those objects.

We can also filter this view to a particular range in time, for example a range where we went from low to high heap usage:

We can then use this filtered view and drill down through the stack trace to find methods of interest:

Explore

Narrow down through some periods of time where our heap rose quickly and then was collected. Look at the memory reclaimed after each collection.

Follow Ups

• What are the most commonly allocated classes? Where do they come from?
• Are there any classes we own that are also high on the allocation list?
• Expand the memory usage chart and only chart the Used Heap, do you notice a pattern?
  • What do you think caused the flat line at the end of the chart?

6 - I/O Operations

The I/O pages can provide context of what external resources you are utilizing from you code base, and relate it to other latency events.

For the purpose of our workshop service, we are doing network I/O, and therefore will look at the Socket I/O page.

From this page, we can gain context of what host(s) we are calling, with what frequency, and the cost associated with those calls:

We can then filter on a particular host and port and drill down into a particular piece of code responsible for that call:

Explore

Filter through the total I/O time and explore a couple of events with high I/O.

Follow Ups

• What remote services are we interacting with?
• How long are we interacting with them and how many invocations?
• How many times did we make calls and what threads were tied to those calls?

7 - References

• JDK Mission Control User Guide
• Hunting down code hotspots with JFR