Several years ago, I gave a presentation at EclipseCon 2016 on “Optimising Eclipse Plug-ins” in which I talked about a few different ways of making Eclipse faster, at least from a start-up and memory usage perspective.

The presentation wasn’t recorded, but is available on SpeakerDeck as well as a narrated copy I recorded subsequently at Vimeo.

One of the techniques I discussed was using Java Flight Recorder as a means to record how long bundles take to start up, since the main cost of starting up Eclipse (or other OSGi applications) is how long it takes for the bundles to move into the STARTED state. Bundles that have a Bundle-Activator can slow this down, and since the majority of OSGi frameworks have a means to start up bundles sequentially, can lead to a lesser user experience.

At the original time of writing, JFR was still a commercial feature (requiring -XX:+UnlockCommercialFeatures setting and the wrath of licensing) in Java 8, and the API was evolving in Java 9 and onwards. However, now that Java 11 has been released, we have a free (both as in beer and in speech) implementation that we can code against in order to work as expected.

A number of API changes meant that the code needed some TLC, and so I recently uploaded a new version of the JFRBundleListener project to GitHub. The project can be downloaded and installed into an OSGi runtime (or Eclipse application) to find out where the start-up costs lie. At the present time, I have not published it anywhere for binary consumption.

The README.md contains more information about how to use it, but the TL;DR is:

• Build and install the bundle with a low start level (e.g. 1) so that it tracks all subsequent bundle activation
• Start your OSGi framework or Eclipse application with the magic invocation to start JFR recording, e.g. -XX:StartFlightRecording=filename=/tmp/dump.jfr,dumponexit=true,disk=true
• Load and inspect the recording into Java Mission Control, or use the embedded java -jar JFRBundleListener.jar < /tmp/dump.jfr > /tmp/stacks.txt to generate a stacks list that can be processed by FlameGraph.pl
• Use Brendan Gregg’s flamegraph tool to create an interactive SVG flamegraph.pl --hash --countname ms < /tmp/stacks.txt > /tmp/bundles.svg

The resulting SVG looks something like this:

Custom JFR events

The API for interacting with JFR has improved significantly since its first inception in Java 8. I am looking forward to the backport of Java 11 to Java 8 to improve the experience significantly there.

To create a custom event, subclass the jdk.jfr.Event class. Provided that it has public fields of a known Java primitive or String, it will be written out when commanded. The JFRBundleEvent class is used to surface an OSGi BundleEvent, and so persists pertinent data to the JFRBundleEvent class upon creation.

These are created when receiving (synchronous) events with the SynchronousBundleListener implemented in the JFRBundleListener class. To mark a span, the event has begin() called at the start of a bundle coming on-line, and end() once it has finished. The commit() ensures that this bundle event is recorded; provided that the commit() occurs at some point later, and that the object is not reused in the meantime, it could be done at a later time.

The event information is recorded with specific key fields; they are identified using the field name in the class, or the one specified with the @Name annotation as defined in the event itself. For simplicity, I have chosen the OSGi bundle headers as the identifiers in the event, which may make post-processing it easier.

Processing JFR files

Similarly, the API for processing a JFR file has become significantly better. There is a helper method RecordingFile.readAllEvents() which translates a dump file at a given path into a list of RecordedEvent objects, or it can be used as an iterator to read through all events.

Events are identified by type; if not specified then the fully qualified name of the event class is used. This makes it easy to filter out specific events from the log, although it may be desirable that they are combined with other JFR events (e.g. thread sleeping, class loading, garbage collections etc.) in the log.

The JFRFlameGraph implementation provides a means to go through the log file, and generate a stack of bundle startup to allow for investigation as to why something is taken so long.

It prunes the list of events in the JFR recording to only include those JFRBundleEvent of interest, and then builds up a sorted data structure based on the earliest start-up time recorded. These are then interactively popped off to write out events before the end time, so that the resulting file contains a list of the bundles starting up:

...
Start-Level...;org.eclipse.ui.trace;org.eclipse.core.runtime;org.eclipse.equinox.preferences 28
Start-Level...;org.eclipse.ui.trace;org.eclipse.core.runtime;org.eclipse.core.contenttype;org.eclipse.equinox.registry 877
Start-Level...;org.eclipse.ui.trace;org.eclipse.core.runtime;org.eclipse.core.contenttype 6
Start-Level...;org.eclipse.ui.trace;org.eclipse.core.runtime;org.eclipse.equinox.app 28
Start-Level...;org.eclipse.ui.trace;org.eclipse.core.runtime 14
Start-Level...;org.eclipse.ui.trace 10
Start-Level...;org.eclipse.update.configurator 977
...

These can then be post-processed with FlameGraph.pl to generate the interactive SVG above.

The code prepends the Java thread name to the stack shown; this allows some threads (such as background Worker-n threads) to be ignored, while focussing on specific threads (such as the main thread and the Start-Level... thread). Since the SVG is interactive, clicking on the thread name will focus the view on just those bundles, which may provide more detailed analysis.

Summary

Java Flight Recorder is available as open source in Java 11, and can be used to export timing information using a custom event format. With sufficient post-processing of the data, it can generate flame graphs that can be more expressive than just looking at numbers.

The API for programmatically interacting with JFR recordings has been significantly improved, and being able to log timely information in conjunction with other events can be a significant bonus in performance analysis.