JFR, async-profiler, and Flame Graphs

JDK Flight Recorder (JFR) is an event recorder built into HotSpot. It records JVM events (GC, compilation, locks, allocation samples, thread sleeps) and application-defined events into a binary file with low overhead, so it can run in production. async-profiler is a separate open-source sampling profiler for HotSpot that draws flame graphs. This lesson shows how to start JFR, define and read events from code, and how to read profiles from both tools.

Item	Purpose
`-XX:StartFlightRecording`, `jcmd JFR.*`	Start and dump recordings without code changes
`jdk.jfr.Recording`	Start, configure, stop, and dump a recording from code
`jdk.jfr.Event`	Base class of custom events
`jdk.jfr.consumer.RecordingFile`	Read events from a `.jfr` file
`jdk.jfr.consumer.RecordingStream`	Receive events while they are recorded
async-profiler `cpu`, `alloc`, `lock`, `wall`	Sample where time, allocation, and contention come from
Flame graph	A picture of many stack samples merged by common prefix

The examples write recordings to temporary files and print event counts and sorted event names, never times or stack addresses.

Example 1: a custom event, recorded and read back

A custom event is a class that extends jdk.jfr.Event. Calling commit() writes it to every running recording that enables it. RecordingFile.readAllEvents reads a dumped file back as RecordedEvent objects.

Java

import java.nio.file.Files;
import java.nio.file.Path;
import java.util.List;
import jdk.jfr.Event;
import jdk.jfr.Name;
import jdk.jfr.Recording;
import jdk.jfr.consumer.RecordedEvent;
import jdk.jfr.consumer.RecordingFile;

public class FirstRecording {
    @Name("demo.OrderAccepted")
    static class OrderAccepted extends Event {
        long orderId;
    }

    public static void main(String[] args) throws Exception {
        Path file = Files.createTempFile("first", ".jfr");
        try (Recording recording = new Recording()) {
            recording.enable("demo.OrderAccepted");
            recording.start();
            for (long id = 1; id <= 5; id++) {
                OrderAccepted event = new OrderAccepted();
                event.orderId = id;
                event.commit();
            }
            recording.stop();
            recording.dump(file);
        }

        List<RecordedEvent> events = RecordingFile.readAllEvents(file);
        long count = events.stream()
                .filter(e -> e.getEventType().getName().equals("demo.OrderAccepted"))
                .count();
        long idSum = events.stream()
                .filter(e -> e.getEventType().getName().equals("demo.OrderAccepted"))
                .mapToLong(e -> e.getLong("orderId")).sum();
        System.out.println("OrderAccepted events: " + count);
        System.out.println("sum of order ids: " + idSum);
        Files.delete(file);
    }
}

Output

OrderAccepted events: 5
sum of order ids: 15

@Name sets the event type name; without it, the name is the fully qualified class name. A new Recording enables nothing until enable is called or a configuration is passed to its constructor. The file also holds metadata events that JFR always writes, which is why the program filters by name.

Example 2: event fields, labels, and duration

An event measures a duration when the code calls begin() before the work and end() (or commit()) after it. @Label, @Category, and @Description are metadata that tools such as JDK Mission Control display. shouldCommit() returns false when the event is disabled or below its threshold, so expensive field values are computed only when needed.

Java

import java.nio.file.Files;
import java.nio.file.Path;
import java.util.TreeMap;
import jdk.jfr.Category;
import jdk.jfr.Event;
import jdk.jfr.EventType;
import jdk.jfr.Label;
import jdk.jfr.Name;
import jdk.jfr.Recording;
import jdk.jfr.consumer.RecordedEvent;
import jdk.jfr.consumer.RecordingFile;

public class TimedEvents {
    @Name("demo.Match")
    @Label("Order Match")
    @Category({"Demo", "Matching"})
    static class MatchEvent extends Event {
        @Label("Symbol") String symbol;
        @Label("Fills") int fills;
    }

    static int match(String symbol, int qty) {
        MatchEvent event = new MatchEvent();
        event.begin();
        int fills = qty / 100;                 // the work being measured
        event.end();
        if (event.shouldCommit()) {
            event.symbol = symbol;
            event.fills = fills;
            event.commit();
        }
        return fills;
    }

    public static void main(String[] args) throws Exception {
        Path file = Files.createTempFile("timed", ".jfr");
        try (Recording r = new Recording()) {
            r.enable("demo.Match");
            r.start();
            match("AAPL", 300);
            match("MSFT", 500);
            match("AAPL", 200);
            r.stop();
            r.dump(file);
        }
        TreeMap<String, Integer> fillsBySymbol = new TreeMap<>();
        boolean durationsValid = true;
        for (RecordedEvent e : RecordingFile.readAllEvents(file)) {
            if (!e.getEventType().getName().equals("demo.Match")) continue;
            fillsBySymbol.merge(e.getString("symbol"), e.getInt("fills"), Integer::sum);
            durationsValid &= !e.getDuration().isNegative();
        }
        EventType type = EventType.getEventType(MatchEvent.class);
        System.out.println("label: " + type.getLabel());
        System.out.println("category: " + type.getCategoryNames());
        System.out.println("fills by symbol: " + fillsBySymbol);
        System.out.println("durations non-negative: " + durationsValid);
        Files.delete(file);
    }
}

Output

label: Order Match
category: [Demo, Matching]
fills by symbol: {AAPL=5, MSFT=5}
durations non-negative: true

Each event carries a start time, a duration, and the committing thread. By default it also carries a stack trace, which costs time at commit; @StackTrace(false) on the class turns that off for high-rate events.

Example 3: built-in JVM events and thresholds

Built-in events are named jdk.*. A threshold drops events shorter than a given duration, which is how JFR keeps the cost of lock and I/O events low. Here jdk.ThreadSleep records with threshold 0, and the custom event is given a one-hour threshold, so no instance of it is kept.

Java

import java.nio.file.Files;
import java.nio.file.Path;
import java.time.Duration;
import java.util.Map;
import java.util.TreeMap;
import jdk.jfr.Event;
import jdk.jfr.Name;
import jdk.jfr.Recording;
import jdk.jfr.consumer.RecordedEvent;
import jdk.jfr.consumer.RecordingFile;

public class BuiltInEvents {
    @Name("demo.Quick")
    static class Quick extends Event {}

    public static void main(String[] args) throws Exception {
        Path file = Files.createTempFile("builtin", ".jfr");
        try (Recording r = new Recording()) {
            r.enable("jdk.ThreadSleep").withThreshold(Duration.ZERO);
            r.enable("jdk.GarbageCollection");
            r.enable("demo.Quick").withThreshold(Duration.ofHours(1));
            r.start();
            for (int i = 0; i < 3; i++) Thread.sleep(5);
            System.gc();
            for (int i = 0; i < 10; i++) {
                Quick q = new Quick();
                q.begin();
                q.commit();
            }
            r.stop();
            r.dump(file);
        }
        Map<String, Integer> counts = new TreeMap<>();
        for (RecordedEvent e : RecordingFile.readAllEvents(file)) {
            String name = e.getEventType().getName();
            if (name.equals("jdk.ThreadSleep") && !e.getThread().getJavaName().equals("main")) continue;
            if (name.equals("jdk.ThreadSleep") || name.equals("demo.Quick")) counts.merge(name, 1, Integer::sum);
            if (name.equals("jdk.GarbageCollection")) counts.put(name + " seen", 1);
        }
        System.out.println(counts);
        Files.delete(file);
    }
}

Output

{jdk.GarbageCollection seen=1, jdk.ThreadSleep=3}

demo.Quick is missing from the map because all ten events lasted less than an hour. The sleep events come from the main thread; the filter excludes JVM threads that may also sleep. The GC count is printed as "seen" because System.gc() can produce more than one jdk.GarbageCollection event depending on the collector.

Example 4: streaming events with RecordingStream

RecordingStream (Java 14) delivers events to callbacks while the recording runs, so a service can react to its own events, for example export them as metrics. Events arrive in batches about once per second, so the program waits on a latch instead of sleeping.

Java

import java.util.concurrent.CountDownLatch;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicLong;
import jdk.jfr.Event;
import jdk.jfr.Name;
import jdk.jfr.consumer.RecordingStream;

public class StreamingEvents {
    @Name("demo.Reject")
    static class Reject extends Event {
        String reason;
    }

    public static void main(String[] args) throws Exception {
        CountDownLatch received = new CountDownLatch(4);
        AtomicLong limitRejects = new AtomicLong();
        try (RecordingStream stream = new RecordingStream()) {
            stream.enable("demo.Reject");
            stream.onEvent("demo.Reject", e -> {
                if (e.getString("reason").equals("LIMIT")) limitRejects.incrementAndGet();
                received.countDown();
            });
            stream.startAsync();
            for (String reason : new String[] {"LIMIT", "PRICE", "LIMIT", "HALTED"}) {
                Reject r = new Reject();
                r.reason = reason;
                r.commit();
            }
            boolean all = received.await(30, TimeUnit.SECONDS);
            System.out.println("all events received: " + all);
        }
        System.out.println("LIMIT rejects: " + limitRejects.get());
    }
}

Output

all events received: true
LIMIT rejects: 2

The callbacks run on a JFR thread, so shared counters use atomics (atomics and CAS). RecordingStream keeps the stream data in its own repository, and closing the stream stops it. EventStream.openRepository() reads the live stream of a recording that another component started.

Example 5: summarizing a recording by event type

Tools such as jfr summary count events per type. The same report in code reads the file once and groups by name, which is the basis of automated checks in a performance test (for example, "no jdk.JavaMonitorEnter events over 10 ms").

Java

import java.nio.file.Files;
import java.nio.file.Path;
import java.util.Map;
import java.util.TreeMap;
import jdk.jfr.Event;
import jdk.jfr.Name;
import jdk.jfr.Recording;
import jdk.jfr.consumer.RecordedEvent;
import jdk.jfr.consumer.RecordingFile;

public class Summary {
    @Name("demo.Quote") static class Quote extends Event { double price; }
    @Name("demo.Trade") static class Trade extends Event { long qty; }

    public static void main(String[] args) throws Exception {
        Path file = Files.createTempFile("summary", ".jfr");
        try (Recording r = new Recording()) {
            r.enable("demo.Quote");
            r.enable("demo.Trade");
            r.start();
            for (int i = 0; i < 7; i++) { Quote q = new Quote(); q.price = 100 + i; q.commit(); }
            for (int i = 0; i < 2; i++) { Trade t = new Trade(); t.qty = 50; t.commit(); }
            r.stop();
            r.dump(file);
        }
        Map<String, Integer> counts = new TreeMap<>();
        try (RecordingFile in = new RecordingFile(file)) {
            while (in.hasMoreEvents()) {
                RecordedEvent e = in.readEvent();
                String name = e.getEventType().getName();
                if (name.startsWith("demo.")) counts.merge(name, 1, Integer::sum);
            }
        }
        counts.forEach((name, n) -> System.out.println(name + " " + n));
        Files.delete(file);
    }
}

Output

demo.Quote 7
demo.Trade 2

RecordingFile reads one event at a time, so large recordings do not have to fit in memory.

Example 6: JFR from the command line and jcmd

A recording usually starts without code changes. -XX:StartFlightRecording starts one at JVM launch, and jcmd controls recordings in a running JVM by process id. The profile settings sample more often than default, at higher cost. The commands below are representative, not run here.

Text

java -XX:StartFlightRecording=duration=60s,settings=profile,filename=app.jfr -jar app.jar

jcmd <pid> JFR.start name=incident settings=profile maxage=10m
jcmd <pid> JFR.dump name=incident filename=incident.jfr
jcmd <pid> JFR.stop name=incident

jfr summary incident.jfr
jfr print --events jdk.ExecutionSample incident.jfr
jfr view hot-methods incident.jfr

Event	Shows
`jdk.ExecutionSample`	Sampled Java stacks of running threads (CPU profile)
`jdk.ObjectAllocationSample`	Allocation sites, throttled by bytes allocated
`jdk.JavaMonitorEnter`	Contended `synchronized` entries over the threshold
`jdk.ThreadPark`	Parking in `java.util.concurrent` locks over the threshold
`jdk.GarbageCollection`, `jdk.GCPhasePause`	Collections and pauses (GC fundamentals)
`jdk.SafepointBegin`	Safepoint operations (safepoints)

maxage and maxsize turn a recording into a ring buffer: JFR keeps only the recent data and a dump captures the minutes before an incident.

Example 7: async-profiler and flame graphs

Many sampling profilers ask each thread for its stack only at a safepoint, so samples land on safepoint polls (loop back-edges, method returns) and never inside a counted loop with no poll. This is safepoint bias: the profile blames the wrong lines. async-profiler avoids it by using AsyncGetCallTrace from a signal handler together with Linux perf_events, so it samples a thread wherever it is, including native and kernel frames. JFR's jdk.ExecutionSample also samples outside safepoints.

async-profiler is not installed here; the usage below is representative.

Text

asprof -e cpu   -d 30 -f cpu.html   <pid>    # on-CPU time
asprof -e alloc -d 30 -f alloc.html <pid>    # allocation sites, by bytes
asprof -e lock  -d 30 -f lock.html  <pid>    # contended locks, by wait time
asprof -e wall  -t -d 30 -f wall.html <pid>  # all threads, running or blocked, per thread
java -agentpath:/path/libasyncProfiler.so=start,event=cpu,file=out.html -jar app.jar

A flame graph merges many stack samples. Each box is a frame; its width is the share of samples that contain it; a box sits on top of its caller. Representative excerpt in collapsed-stack form, the text format flame graphs are drawn from (not captured here):

Text

java/lang/Thread.run;Engine.loop;OrderBook.match;TreeMap.getEntry 4210
java/lang/Thread.run;Engine.loop;OrderBook.match;Fill.<init> 980
java/lang/Thread.run;Engine.loop;Json.encode;StringBuilder.append 2630
java/lang/Thread.run;Engine.loop;Json.encode;Arrays.copyOf 1400

Reading rules:

Look for wide boxes near the top: the plateaus are where samples end, so that frame itself used the CPU. Here TreeMap.getEntry and the JSON encoding dominate.
The x-axis is sorted alphabetically, not by time. Order between siblings means nothing.
In an alloc graph, width is bytes allocated, and the top frame is the allocation site (Arrays.copyOf from a growing StringBuilder).
In a lock graph, width is time spent waiting for a lock, and the stack shows who waited, not who held it.
A wall graph includes sleeping and blocked threads, so idle pool threads appear as wide park frames; filter by thread (-t) to find the request thread.

Interview points

JFR is built into HotSpot, records events into a ring buffer with low overhead, and is meant to run in production.
Custom events extend jdk.jfr.Event, use begin, end, shouldCommit, and commit, and are enabled by name.
Thresholds drop short events; that keeps lock and I/O events cheap.
RecordingFile reads a dump; RecordingStream delivers events live to callbacks.
Safepoint bias makes safepoint-based profilers attribute time to poll locations; async-profiler and JFR's execution sampler avoid it.
Flame graph width is sample share; the x-axis is not time; the top edge is where the cost is.
cpu shows on-CPU time; wall shows blocked time too; alloc shows bytes; lock shows contention.

Summary

-XX:StartFlightRecording and jcmd JFR.start/dump/stop control recordings without code.
Recording.enable(name) turns on an event type; withThreshold and withPeriod configure it.
@Name, @Label, @Category, and @StackTrace describe custom events.
RecordedEvent exposes fields by name (getLong, getString), start time, duration, and thread.
async-profiler samples via signals and perf_events, including native and kernel frames.
A flame graph is merged stack samples; plateaus at the top are the hot code.