16.5 Profiling & Flame Graphs

Advanced

What you will learn

1. The profiling question, stated precisely.

2. The rootless sampler: what 200 Hz of /proc state teaches (with live receipts).

3. Flame graphs — how to read one, how to make one when perf is available.

4. The decision tree: sampler → perf → eBPF, and when each is the right weapon.

1. The question, precisely

"There's CPU" is not a sentence. The profiling question is:

Of the CPU seconds this worker burned, which functions consumed them — and is that distribution what we expect?

NGINX's healthy answer (Module 1's model): epoll bookkeeping, syscalls (read/write/sendfile/accept), TLS crypto, compression, and buffer copies. The unhealthy answers — one module pinning a core, lock contention serializing workers, gzip level 11 on a hot route — look identical from the outside (high CPU, slow responses) and completely different from the inside.

2. The rootless sampler

The instrument is a rootless sampler — a ~15-line loop (shell or Python) run at 200 Hz, reading the same-uid /proc tree: the Lesson 16.3 kit turned into an instrument. What it measures:

• CPU%: /proc/<pid>/stat jiffies, sampled at both ends of the window (the scheduler's own accounting — you can't get more authoritative without perf counters);

• R/S/D distribution: state samples — running vs sleeping vs disk-wait (the shape of the time);

• wchan census: what the kernel reports each sample while sleeping.

Live receipts from a running server under generated load (real):

    PID   CPU%    R%    S%    D%  top wchan
  17661  16.0%   22%   78%    0%  do_epoll_wait
  17724  16.0%   25%   75%    0%  do_epoll_wait

reading: CPU% = scheduler-reported jiffies / wall time;
         R/S/D = running / sleeping / disk-wait samples;
         wchan = kernel wait channel (epoll_wait = healthy loop)

How to read it like a profiler:

• Both workers identical (16%/16%, same wchan) — the event loop's fair sharing is intact; no worker is "the slow one." (When they differ, you've just halved the search space — kernel socket hashing, reuseport imbalance, or one pathological connection.)

• S% in the 70s with do_epoll_wait dominant — the workers are waiting for work, not working: this fleet has headroom. (High CPU mystery + high S% + low R% = the time isn't going to the workers — check the master, the kernel, or your measurement.)

• D% nonzero and climbing — disk-wait: spills (Module 9's buffered-body receipts), a slow tmpfs, an NFS misadventure.

• R% high, CPU% high, wchan noise — genuinely CPU-saturated. NOW you want the flame graph — because now you know the fire is real and in this worker.

What the sampler can't say: which function — that's the symbol-level answer only perf/gdb/eBPF give. The sampler narrows WHERE; the profiler names WHY.

3. Flame graphs — reading and making

When you have perf (or a friendly admin), the canonical flow (Brendan Gregg's invention, unchanged in spirit):

# 1. sample stacks (perf on the workers, or system-wide)
#    (pidfile under the debug build's own prefix — Lesson 16.2's install)
perf record -F 99 -g -p $(pgrep -d, -P $(cat logs/nginx.pid)) -- sleep 30

# 2. fold stacks into the flamegraph format
perf script | stackcollapse-perf.pl > out.folded

# 3. render
flamegraph.pl out.folded > flame.svg

Reading one is a minute to learn:

• Width = share of samples the function was in (CPU share). A wide tower is where the time went.

• Height = stack depth at that moment. Tall thin towers are deep (often request-processing) stacks.

• Color is decorative (warm = hot-looking); alphabetical sorting makes frames findable.

• A plateau (wide flat top) = a function burning CPU itself — gzip's deflate, ngx_ssl_do_handshake, memcpy. A wide base with a narrow top = many short stacks through one dispatcher (accept/epoll noise — usually fine).

• Diff two flame graphs (before/after your Module 15 module, say) and the regression's tower jumps out visually — the golden-diff habit (Lesson 12.3 / Lesson 14.5), in picture form.

The eBPF era adds live versions of the same picture ( bpftrace one-liners, perf-tools); the reading skill is identical — learn the shape grammar once.

4. The decision tree

Is CPU high? (sampler/stub_status — Lesson 12.4)
 ├─ no -> the problem is elsewhere (latency? upstream? cache?) — Module 12's logs
 ├─ yes, D-state heavy -> IO story — check fd table, mounts, spills (9.2)
 ├─ yes, one worker only -> per-worker asymmetry — reuseport/affinity/one bad conn
 └─ yes, all workers, R-heavy, epoll-quiet
      ├─ perf available?  -> flame graph; name the plateau
      ├─ gdb available?   -> poor-man's profiler: loop 'gdb -p PID -ex bt -batch';
      │                      stack histograms = flame graph, slower
      └─ neither          -> sampler shape + debug-log narration + bisection:
                             comment out half the modules, reload, re-sample.
                             (The oldest profiler: change one thing, measure.)

That last branch — bisection — deserves respect: with the sampler's shape, the debug log's narrative, and Lesson 14.4's reload discipline, you can binary-search a CPU regression across modules in log₂(n) reloads. It's how people found hot loops before perf existed, and it still closes tickets.

Try it yourself

• Write the sampler: a loop reading /proc/<pid>/stat and /proc/<pid>/wchan for every nginx worker, printing one line per tick, run under load — then check the shape by eye: fleet found, epoll heartbeat, per-worker rows (the receipts above are the shape to match).

• Break the shape deliberately: ab/ wrk-style load against the gzip-heavy :9701 from Module 15 while sampling your own workers — watch R% climb and S% fall; that's the "genuinely busy" signature.

• If you have a perf-enabled machine: run the three commands on any nginx you own and read your first real flame — the towers are prettier than the receipts, but the receipts trained your eyes.

Q&A

Q: Why 99 Hz / 200 Hz — not faster? A: Sampling cost scales with frequency; ~100 Hz catches seconds-scale hot spots with <1% overhead. Millisecond mysteries need tracing, not sampling — different tools, different questions.

Q: The sampler shows low CPU but users report slowness? A: Then the time is going to waiting, not computing: upstream latency (Lesson 12.3's $upstream_response_time), queueing (Module 7's limit_*), or the network. The profiler's greatest gift is sometimes the alibi.

Q: Profile in production? A: Sampler: always (it's free). perf: at 99 Hz on a canary worker, fine. Bisection reloads: staging. Cores + gdb: on crash, obviously. Escalate in proportion to evidence.

Q: What about memory profiling? A: Different instrument: nginx's own allocations (debug-log malloc: narration, 16.2), /proc/<pid>/status VmRSS trending (16.3), and valgrind/ASAN builds for the deep cases (a Module 15-shaped build with sanitizers). Flame graphs are CPU's tool; memory leaks are told by slopes.

Takeaways

• State the question precisely — which functions consumed the CPU — before touching any tool; the instrument follows the hypothesis.

• The rootless sampler answers shape: CPU%, R/S/D mix, and the wchan census — identical workers at 16% sleeping in do_epoll_wait is the picture of health; D-state climbing is the IO alarm; R-heavy-all-workers is when the fire is real.

• Flame graphs: width = share, height = depth, plateaus = the culprit; perf record → collapse → render when you can, and diff them like Lesson 12.3 golden-diffs.

• The escalation is a tree: sampler → D-state check → per-worker asymmetry → perf/gdb/bisection. Every branch ends in a receipt — which is the whole series' promise.