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.
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
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
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.
- Load and inspect the recording into Java Mission Control, or use the embedded
java -jar JFRBundleListener.jar < /tmp/dump.jfr > /tmp/stacks.txtto 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
class is used to surface an OSGi
BundleEvent, and so persists pertinent data
JFRBundleEvent class upon creation.
These are created when receiving (synchronous) events with the
SynchronousBundleListener implemented in the
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
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.
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
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
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.
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.