Profiling JVM Safepoint Delays at Scale with JDK Flight Recorder and eBPF — code snippets

snippet-1.txt

package com.mycompany.observability;

import jdk.jfr.Configuration;
import jdk.jfr.Recording;
import java.io.IOException;
import java.nio.file.Paths;
import java.text.ParseException;
import java.time.Duration;

public class JfrSafepointProfiler {
    public static void startProfiling(String outputPath, Duration duration) throws IOException, ParseException {
        // Load the default profile configuration as a baseline
        Configuration config = Configuration.getConfiguration("profile");
        Recording recording = new Recording(config);
        
        // Enable and adjust thresholds for specific safepoint lifecycle events
        recording.enable("jdk.SafepointBegin").withThreshold(Duration.ofMillis(1));
        recording.enable("jdk.SafepointStateSynchronization").withThreshold(Duration.ofMillis(1));
        recording.enable("jdk.SafepointWaitBlocked").withThreshold(Duration.ofMillis(1));
        recording.enable("jdk.SafepointCleanup").withThreshold(Duration.ofMillis(1));
        recording.enable("jdk.SafepointEnd");
        
        recording.setDestination(Paths.get(outputPath));
        recording.setMaxAge(Duration.ofHours(1));
        recording.start();
        
        System.out.printf("JFR Safepoint profiling started. Writing output to: %s%n", outputPath);
        
        // Schedule clean termination
        new Thread(() -> {
            try {
                Thread.sleep(duration.toMillis());
                recording.stop();
                recording.close();
                System.out.println("JFR Safepoint profiling completed successfully.");
            } catch (Exception e) {
                System.err.println("Failed to stop JFR recording: " + e.getMessage());
            }
        }).start();
    }
}

snippet-2.txt

<?xml version="1.0" encoding="UTF-8"?>
<configuration version="2.0" label="Aggressive Safepoint Profiling" description="Low overhead profile targeting JVM Safepoints and TTSP anomalies" provider="Moh Ashari Muklis">
  <event name="jdk.SafepointBegin">
    <setting name="enabled">true</setting>
    <setting name="threshold">0 ms</setting>
  </event>
  <event name="jdk.SafepointStateSynchronization">
    <setting name="enabled">true</setting>
    <setting name="threshold">0 ms</setting>
  </event>
  <event name="jdk.SafepointWaitBlocked">
    <setting name="enabled">true</setting>
    <setting name="threshold">0 ms</setting>
  </event>
  <event name="jdk.SafepointCleanup">
    <setting name="enabled">true</setting>
    <setting name="threshold">0 ms</setting>
  </event>
  <event name="jdk.SafepointEnd">
    <setting name="enabled">true</setting>
  </event>
</configuration>

snippet-3.sh

# Extract and format all safepoint events from a JFR recording file.
# Sorts the output by the duration of the state synchronization phase (TTSP).

jfr print --events "jdk.SafepointBegin,jdk.SafepointStateSynchronization" production_dump.jfr | \
awk '
/jdk.SafepointBegin/ {
    split($0, t_arr, " ");
    time_stamp = t_arr[2];
}
/jdk.SafepointStateSynchronization/ {
    in_sync = 1;
}
/duration =/ && in_sync {
    match($0, /[0-9]+(\.[0-9]+)?\s*(ms|s|us)/);
    duration_str = substr($0, RSTART, RLENGTH);
    print time_stamp " | TTSP: " duration_str;
    in_sync = 0;
}
' | sort -t':' -k3 -n

snippet-4.txt

package com.mycompany.workload;

public class SafepointBlockingTask implements Runnable {
    private static final int ITERATIONS = 2_000_000_000;
    private final double[] data = new double[1024];

    public SafepointBlockingTask() {
        for (int i = 0; i < data.length; i++) {
            data[i] = Math.random();
        }
    }

    @Override
    public void run() {
        double sum = 0;
        // Counted loop: JIT optimizes out safepoint checks in the compiled loop body
        for (int i = 0; i < ITERATIONS; i++) {
            int index = i & 1023;
            // Calculations to prevent compiler dead-code elimination
            sum += Math.sin(data[index]) * Math.cos(i);
        }
        System.out.println("Computation output: " + sum);
    }
}

snippet-5.txt

#pragma init_uprobes

/*
 * bpftrace script to monitor JVM TTSP latency.
 * Hooks into the HotSpot symbol for safepoint synchronization startup.
 * Usage: bpftrace jvm_ttsp.bt -p <PID>
 */

uprobe:/usr/lib/jvm/java-17-openjdk/lib/server/libjvm.so:_ZN20SafepointSynchronize5beginEv {
    @start[tid] = nsecs;
    @safepoint_requested = nsecs;
}

uretprobe:/usr/lib/jvm/java-17-openjdk/lib/server/libjvm.so:_ZN20SafepointSynchronize5beginEv {
    $s = @start[tid];
    if ($s) {
        $duration_us = (nsecs - $s) / 1000;
        @ttsp_duration_us = lhist($duration_us, 0, 100000, 5000); // 0 to 100ms range
        delete(@start[tid]);
    }
    @safepoint_requested = 0;
}

// Trace scheduling switches while a safepoint request is active
tracepoint:sched:sched_switch /@safepoint_requested != 0/ {
    // Record the on-CPU duration of threads running during the sync phase
    @running_tids[args->prev_pid] = nsecs - @safepoint_requested;
}

interval:s:10 {
    printf("--- TTSP Latency Distribution (microseconds) ---\n");
    print(@ttsp_duration_us);
    
    printf("\n--- Threads running during active Safepoint sync (TID & Duration ns) ---\n");
    print(@running_tids);
    
    clear(@running_tids);
}

snippet-6.py

from bcc import BPF
import time
import sys

# BCC script to trace user-space stacks of threads blocking JVM safepoint entry.
# Hooks JVM's libjvm.so internal symbols.

if len(sys.argv) < 3:
    print("Usage: python ttsp_stack_tracer.py <PID> <PATH_TO_LIBJVM>")
    sys.exit(1)

pid = sys.argv[1]
libjvm_path = sys.argv[2]

ebpf_program = """
#include <uapi/linux/ptrace.h>
#include <linux/sched.h>

BPF_HASH(start_ns, u32, u64);
BPF_STACK_TRACE(stack_traces, 2048);
BPF_HASH(blocked_stacks, u32, int);

int trace_safepoint_begin(struct pt_regs *ctx) {
    u32 tid = bpf_get_current_pid_tgid() & 0xFFFFFFFF;
    u64 ts = bpf_ktime_get_ns();
    start_ns.update(&tid, &ts);
    return 0;
}

int trace_safepoint_end(struct pt_regs *ctx) {
    u32 tid = bpf_get_current_pid_tgid() & 0xFFFFFFFF;
    u64 *ts = start_ns.lookup(&tid);
    if (ts) {
        u64 delta = bpf_ktime_get_ns() - *ts;
        // Threshold: If sync takes more than 15ms (15,000,000 ns)
        if (delta > 15000000) {
            int stack_id = stack_traces.get_stackid(ctx, BPF_F_USER_STACK);
            if (stack_id >= 0) {
                blocked_stacks.update(&tid, &stack_id);
            }
        }
        start_ns.delete(&tid);
    }
    return 0;
}
"""

b = BPF(text=ebpf_program)

# Attach uprobes using the target JVM Process ID and absolute library path
b.attach_uprobe(name=libjvm_path, sym="_ZN20SafepointSynchronize5beginEv", fn_name="trace_safepoint_begin", pid=int(pid))
b.attach_uretprobe(name=libjvm_path, sym="_ZN20SafepointSynchronize5beginEv", fn_name="trace_safepoint_end", pid=int(pid))

print(f"Tracing JVM PID {pid} for safepoint delays > 15ms. Press Ctrl+C to stop.")

try:
    while True:
        time.sleep(1)
except KeyboardInterrupt:
    pass

print("\n--- Blocked Stack Traces Detected During TTSP Windows ---")
blocked_stacks = b["blocked_stacks"]
stack_traces = b["stack_traces"]

for k, v in blocked_stacks.items():
    print(f"\nThread OS ID (TID): {k.value} was running when VM Thread was waiting.")
    for addr in stack_traces.walk(v.value):
        print(f"  [Instruction Address] {hex(addr)}")