Profiling with JFR and async-profiler

Profiling is how you replace "I think it is the serialisation" with a measurement. Two tools cover almost everything: JFR, which ships with the JDK and is cheap enough to leave running, and async-profiler, which produces the most accurate flame graphs available.

JFR#

# On a running process
jcmd <pid> JFR.start name=diag settings=profile duration=120s filename=/tmp/rec.jfr
 
# At launch, continuous with a rolling buffer — the production configuration
-XX:StartFlightRecording=name=continuous,settings=profile,maxsize=512m,maxage=1h,disk=true
 
# Dump the last hour when something happens
jcmd <pid> JFR.dump name=continuous filename=/tmp/incident.jfr

That third command is the point of JFR. A rolling recording means that when an alert fires at 03:00 you already have a full profile of the minutes leading up to it — CPU, allocation, GC, locks, exceptions, I/O and thread states, all on one timeline. Nothing else gives you that retrospectively.

Two settings ship by default: default (about 1% overhead, suitable for permanent use) and profile (about 2%, more sampling detail). Both are safe in production; the naming is misleading, since default is the low-overhead one.

Open the recording in JDK Mission Control. The views that earn their time:

The Lock Instances and Thread Latencies views are the ones most people never open, and they answer questions a CPU profile cannot: a request that is slow because it waited is invisible in a CPU profile and obvious here.

Safepoint bias#

The JIT inserts safepoint polls at method returns and loop back-edges — and aggressively optimises them out of tight, inlined, counted loops. So the hottest code in an application is often the code with the fewest safepoints, and a safepoint-biased profiler systematically under-reports it while over-reporting whatever method happens to sit at the next safepoint.

The practical result is a profile that confidently names the wrong method. Both async-profiler and JFR use signal-based sampling and do not have this problem, which is why they are the tools to use.

async-profiler#

# CPU — what is burning cores
./asprof -d 30 -e cpu -f cpu.html <pid>
 
# Allocation — what is producing garbage, by call site
./asprof -d 30 -e alloc -f alloc.html <pid>
 
# Wall clock — what is making requests slow, including waiting
./asprof -d 30 -e wall -t -f wall.html <pid>
 
# Lock contention
./asprof -d 30 -e lock -f lock.html <pid>
 
# Two profiles compared, as a differential flame graph
./asprof -d 30 -e cpu -f after.html <pid>

It requires -XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints to resolve inlined frames correctly — without it, inlined methods are attributed to their caller and the graph is misleading.

The allocation mode is the one that pays for itself. It samples TLAB allocations and shows the exact call sites producing garbage, sorted by bytes. Reducing allocation is usually the highest-leverage performance change available, and this is how you find where to do it — see GC logs and tuning.

Reading a flame graph#

        ┌──────────────────────────────────────────┐
        │            handleRequest  100%           │   ← every sample
        ├──────────────────┬───────────────────────┤
        │  parseJson 45%   │   queryDatabase 52%   │   ← direct callees
        ├─────────┬────────┼──────────┬────────────┤
        │ read 12%│ map 33%│ jdbc 20% │ mapRows 31%│
        └─────────┴────────┴──────────┴────────────┘

Three rules:

Width is time. A frame's width is the fraction of samples in which it appeared on the stack. Wider means more expensive.

Height is call depth, not cost. A tall narrow tower is a deep call chain that is barely used; a short wide plateau is where the time actually goes.

The x-axis is alphabetical, not chronological. Left-to-right ordering carries no meaning at all — it exists only so that identical stacks merge into one wide frame. This is the most common misreading.

What you are hunting for is a wide plateau: a single frame that occupies a large fraction of the width with little above it. That is code doing work itself rather than delegating, and it is where optimisation has leverage. A common surprise is finding String.format, a regex, or a logging call occupying 20% of a hot path.

CPU versus wall clock#

CPU mode                          Wall-clock mode
  parseRequest      30ms  (60%)     queryDatabase   420ms  (84%)
  buildResponse     15ms  (30%)     parseRequest     30ms   (6%)
  serialise          5ms  (10%)     buildResponse    15ms   (3%)
                                    serialise         5ms   (1%)

CPU mode samples only threads that are on-CPU, so the 420ms spent waiting for the database is essentially invisible and parseRequest looks like the problem. Wall-clock mode samples every thread regardless of state, and the actual answer appears immediately.

Use CPU mode when the machine is saturated and you need to reduce work. Use wall-clock mode when latency is the complaint and CPU usage is modest — which describes most web-service performance problems.

Profiling correctly#

Warm up first. The JIT needs thousands of invocations before it compiles and inlines. A profile of the first ten seconds is a profile of the interpreter and tells you nothing about steady state.

Use realistic data. Ten items behave differently from ten thousand: different branch prediction, different cache behaviour, different collection code paths.

Profile in production, or something shaped like it. Local profiles miss network latency, contention from concurrent requests, container CPU limits and real data distributions. JFR's low overhead is what makes production profiling reasonable.

Change one thing, measure again. A flame graph shows where time goes, not what a fix would save. Confirm the improvement with a differential profile rather than assuming.

For micro-benchmarks — comparing two implementations of a method — use JMH instead. Hand-rolled timing loops are defeated by dead-code elimination, constant folding and lack of warm-up, and JMH exists specifically to defeat those.

What gets asked#

"How would you find why a service is slow?" — the answer is a sequence, not a tool: check whether it is CPU-bound or waiting, then use the matching profiler mode, then look for a wide plateau in the flame graph, then confirm the fix with a second profile.

Two details that mark experience: knowing that JFR can run continuously so you have the recording before the incident, and knowing what safepoint bias is — because it explains why a profiler can be confidently wrong.