Three kinds of slow, and which tool sees each one

A profile, a trace and a memory graph answer different questions. Four endpoints that are all "slow" and all need a different instrument, with the query for each.

Why this exists

A latency graph, an SLO burn rate and an alert all say the same thing about all of these: p95 is bad. They cannot say why, and reaching for the wrong instrument costs an afternoon.

inkwell-web ships four endpoints whose only purpose is to be slow in four different ways. platform/demo-traffic drives all of them continuously, so the panels below are never empty — you can open any of them right now and the shape will be there.

1. Busy — /diagnostics/cpu

A tight scoring loop with no I/O.

The instrument: a CPU profile. One frame holds most of the samples. This is the case people picture when they hear "profiler", and it is the only one of the four where that picture is right.

Take it away as a real pprof and rank it yourself:

go tool pprof -top <(curl -sL 'https://console.jung.town/components/inkwell-web/download/profile.pprof?minutes=15')

2. Allocating — /diagnostics/memory

Builds a large intermediate structure and throws it away. Cheap in CPU, expensive in allocations and in resident memory while it runs.

This is the trap. The Ruby push SDK reports process_cpu, so the CPU profile for this endpoint is almost empty — and "the profiler says it is fine" is the wrong conclusion. The evidence is the container's memory metric and the objects_allocated count in the response body, not the flame graph.

The memory profile is a separate axis, in bytes, and only on a build that asked for one (profileRich: true):

/builds/<run>/download/profile.pprof?type=memory

3. Waiting — /diagnostics/waiting

The process is idle the whole time. It costs no CPU and allocates almost nothing. Both profiles are flat, and both are correct.

The instrument: the trace. Only the waterfall shows the gap — and whether the gap is attributable. With UPSTREAM_URL bound the wait is a child span in another service; without it, it is an unexplained hole in this one. That difference is the whole of what distributed tracing buys.

Every response carries the id, so the trace for a request you just made is in the response you already have:

curl -sD- https://production-inkwell.jung.town/inkwell-web-http/diagnostics/waiting?ms=1500 -o /dev/null | grep -i trace

Since the gateway is traced, the root span is the ingress hop — so this also shows how much of the wait was the gateway and how much was the application.

4. Doing it 51 times — /widgets vs /widgets/fast

Two actions returning byte-identical JSON. One runs a query for the widgets and then one per widget for its parts; the other eager-loads and runs two.

The instrument: the trace, and it is unmistakable — a flat wall of SELECT "parts".* spans under one server span. In a profile it is nearly invisible: the CPU is spread thinly across ActiveRecord's query construction with no single frame standing out.

It is also visible in a metric rather than a trace you have to go and find, which is the more useful form:

GET /widgets   36 calls
Part query   1800 calls     <- 50 per request

5. The one a single profile cannot show — the worker's leak

POST /widgets/:id/rollup enqueues rather than doing the work, so the worker's span is parented to the request rather than floating in a trace of its own.

RollupJob keeps an unbounded cache, deliberately. A leak is the hardest shape to see in a demo, because a profile taken once tells you nothing about it and two profiles an hour apart tell you everything. Grafana's Profiles app diffs two time ranges; this is what makes that feature demonstrable rather than theoretical.

ROLLUP_CACHE_BOUNDED=true makes it behave, and the same graph goes flat. Having both behaviours behind one variable is what turns "we fixed the leak" into something you can show somebody.

The summary worth keeping

"Slow" and "busy" are different claims. Profiling answers the second.