Profiling: finding where the time really goes

Key points

• Most JVM profilers sample only at safepoints, and safepoints are not evenly distributed through code. That bias can point at the wrong method entirely - the classic profiler trap.
• async-profiler avoids it by sampling with the OS at arbitrary points, so its picture is closer to the truth. It also profiles allocation and lock contention, not just CPU.
• A flame graph reads width, not height. Width is time spent; height is stack depth. A wide plateau is where the time goes, and a deep narrow spike is usually irrelevant.
• Profile the right thing. CPU profiling finds hot computation; allocation profiling finds GC pressure; wall-clock profiling finds blocking, which CPU profiling cannot see at all.
• That distinction matters: a service that spends its time waiting on a database shows almost no CPU, so a CPU profile looks flat and healthy while the service is unusably slow.
• Profile under realistic load and after warm-up. A cold JVM is running interpreted, so an early profile measures the interpreter rather than your steady-state code.

Example

# CPU profile of a running process, 30 seconds, straight to a flame graph.
$ ./profiler.sh -d 30 -f cpu.html <pid>

# Allocation profile - what is generating garbage, by call site.
$ ./profiler.sh -d 30 -e alloc -f alloc.html <pid>

# Wall clock - includes time BLOCKED, which a CPU profile cannot show.
$ ./profiler.sh -d 30 -e wall -t -f wall.html <pid>

# Lock contention.
$ ./profiler.sh -d 30 -e lock -f lock.html <pid>

# Built in and always available - JDK Flight Recorder, low overhead,
# safe to leave running in production.
$ java -XX:StartFlightRecording=duration=60s,filename=app.jfr -jar app.jar
$ jfr summary app.jfr
$ jfr print --events CPULoad,GCPhasePause,JavaMonitorEnter app.jfr

# Reading a flame graph:
#
#   WIDTH  = share of samples = where time goes      <- the only thing that matters
#   HEIGHT = stack depth                             <- not significance
#   colour = arbitrary, for distinguishing frames only
#
#   Look for a wide plateau. Ignore tall thin towers.

# Which profile answers which question:
#
#   "CPU is pinned"           -> cpu
#   "GC is constant"          -> alloc
#   "slow but CPU is idle"    -> wall   (this is the one people forget)
#   "threads are stuck"       -> lock, or a thread dump

A CPU profile cannot see blocking - if the service is slow while the CPU is idle, you need a wall-clock profile.