Which Request Burned the CPU? Span-Tagged Profiles on Virtual Threads

Trace-linked profiling makes a nice promise: click a slow span, see the code that burned its CPU. I set it up for Stopgap 4.1, and it works. On platform threads. On virtual threads, samples can quietly land on the wrong request, and nothing tells you.

This is the path I took to understand it, from the basics: why you need span-tagged samples to find a slow outlier at all, what a debugging session looks like when it works, how virtual threads break it, and how Go avoids the problem.

A continuous profiler doesn’t record every function call. Every 10ms or so, a timer fires on a busy thread, the profiler grabs that thread’s stack and writes it down. That’s one sample. Pile up thousands and you get a flame graph: the wider a frame, the more CPU it used.

To link profiles to traces, each sample also has to say which request it came from. Pyroscope’s OpenTelemetry extension does it like this:

So the profiler owns the slot: it creates it and reads it. Pyroscope’s span processor only writes to it, once when the span starts and once when it ends. In between, the sampler fires every 10ms or so and picks up whatever is sitting there. Write once, read many times: the span processor never talks to the sampler directly, it just leaves the tag in place for the next tick.

The slot is native thread-local storage, not a Java ThreadLocal. The sampler runs inside a signal handler, which can interrupt the thread anywhere, even mid-GC, so it can’t safely read Java objects. A native slot is plain memory it can read on the spot. That difference matters later.

In Grafana you click a slow span and say “show me only the samples with this span’s id”. That’s the whole trick.

On a plain platform thread, where one request owns one thread from start to finish, this is correct. The thread running the code is the thread holding the tag.

At one sample per 10ms of CPU, a request that burns 30ms of CPU gets about 3 samples. You can’t read a flame graph off 3 samples. It’s noise.

Profiles only make sense in aggregate, and there are two ways to aggregate:

The second one is the entire reason trace-linked profiling is worth the trouble. Keep that in mind, it comes back later.

Say GET /notes has a p50 of 20ms and a p99 of 900ms, and I already know the extra time is CPU. The cause, which I don’t know yet: one note has a few megabytes of text in its body, and every request that returns it spends most of its time serializing that text.

The metrics show those requests as slow. That’s all they show. What took the time, CPU-wise, isn’t in them.

The service-wide flame graph doesn’t help either. Every request serializes JSON, so serialization is a wide frame on any normal day. 99% of the samples come from fast requests, and nothing in the aggregate says which samples came from the slow 1%. The outlier is diluted into the average.

So the idea is to stick together only the samples from the requests that were slow. To find those samples, each one needs a label saying which request it came from. That label is the root span id.

Best case: platform threads, no executor hops. Here’s how the signals hand off.

1. Metric to exemplar. The latency histogram carries exemplars: real trace ids attached to its buckets. The p99 spike has dots on it, and each dot is one actual slow request. Click one.

2. Exemplar to trace. The trace shows something like:

HTTP Request 900ms ├─ SELECT notes 8ms └─ write response 3ms

The child spans add up to about 11ms. So roughly 890ms went into my own code, not the database. Spans tell me which request and which gap. They can’t tell me which function; that’s the profiler’s job.

3. Trace to span profile. Pull only the samples tagged with this span’s id.

Sanity check first: samples × 10ms ≈ CPU time. Around 87 samples means around 870ms of CPU, so the request really was CPU-bound. If there are 3, it was mostly waiting (a lock, the database, a GC pause), and a CPU profile is the wrong tool; that’s a job for child spans, lock profiles or JFR events. This post sticks to the CPU case.

NoteHandler.list ████████████████████ 95% └─ JSON serialize ███████████████████ 90% └─ writeString ██████████████████ 85%

Serialization. Same frame as in the aggregate, but here it’s 90% of the request instead of a normal slice. That’s the note with megabytes of text in its body, and now it’s visible.

4. When one request is too thin: merge and diff. A different case: if each slow request burns only 40ms extra, that’s about 4 samples each. Too few. So:

That’s how you beat the dilution: you choose the samples by span instead of by time.

Why not a simpler label, like the endpoint? I could tag every sample with endpoint=/notes. But that still mixes the fast and slow /notes calls, so the big note stays diluted, just in a smaller pool.

Slowness is only known on the trace side. The span has the duration. A sample only has a stack; it has no idea whether its request turned out slow. The span id is what joins the two: ask the traces which requests were slow, then ask the profiles for those requests’ samples.

A question I had at this point: a request has child spans too, the JDBC queries and the @WithSpan methods. Shouldn’t the span processor write their ids into the slot as well?

It can. The extension has a setting for it, off by default, and a child’s id simply replaces the root’s. Worse, a span’s end clears the slot instead of putting the parent’s id back:

root starts slot = root child starts slot = child child ends slot = empty ← root's id is gone root continues slot = empty ← rest of the request is untagged

Even with the parent restored, the request’s samples end up split across a dozen span ids, and seeing the whole request again means collecting them all and merging.

So carry both: the root id and the current span id. That fixes the fragmentation. Query by root and you get the whole request, same as today. Query by the current span and you get one part of it, and you can merge every serializeNotes span across the slow requests without digging through stacks. That helps when a span is a unit of work rather than one method: a batch item, a block of code spread over several methods, or one method called from two places where only one matters.

On platform threads with mostly synchronous work, carrying both is a fair upgrade if span-level splits matter to you. Otherwise a whole request is the smallest unit with enough samples to read, and one label per request is the right size. On virtual threads, more labels is worse: many more writes, each landing on whatever carrier is underneath at that moment. That matters in the next section.

Everything above assumed one request owns one thread. Helidon doesn’t work that way: it runs every request on a virtual thread.

A virtual thread doesn’t own an OS thread. It gets mounted on a carrier, a real OS thread, while it runs. When it blocks, say on a database call, it unmounts, and later resumes on whichever carrier is free. There are about as many carriers as CPU cores, shared by thousands of virtual threads.

Two different “contexts” are involved, and they live in different places:

And the profiler’s timer fires on the carrier. So every sample reads the carrier’s slot, no matter which virtual thread happens to be sitting on it.

Here’s a made-up but realistic timeline. Two carriers, C1 and C2. Two requests: X (slow: a query, then 870ms of serialization) and Y (fast: a query, then 10ms of work).

Nothing is lost overall. The service-wide flame graph still has every sample. Only the tags are wrong.

A typical handler goes: read from the database, compute, respond. The database read is what unmounts the virtual thread. So the compute step, the exact thing you’re hunting in a CPU-bound p99, is the step most likely to run on a different carrier. Code before the first I/O call is tagged right. Everything after is up for grabs.

Under enough concurrency, a span’s tag is close to a random pick among whatever was in flight. The span view quietly turns back into the time-window aggregate, the very dilution I was trying to escape. It just looks precise.

That’s the part that bugs me. A missing feature is fine. A feature that silently gives you a confident wrong answer is worse.

On a single thread, a span can’t use more CPU than its own duration. If samples × interval is bigger than the span’s duration (Y: 870ms of CPU inside a 20ms span), the tags are wrong.*

• That’s for the JVM setup here. In general, a span’s CPU can be more than its duration: fan its work out to four threads for 20ms and that’s 80ms of CPU in a 20ms span. Go gets this right, since new goroutines inherit their parent’s labels, so there the tell doesn’t apply. Here, only the thread that starts the root span gets the id, so fanned-out work can’t add to the span. Its samples go untagged on a pool thread, or to whichever request the carrier held last on a virtual thread. So for now, anything past the duration is misattribution. It’s a check for today’s bugs, not general advice: once workers carry the id, a span with real parallel work goes past its duration too, and the check stops working.

Once I saw it, it stopped being about virtual threads. It hits anything that runs M user-space tasks on N OS threads: virtual threads, coroutines, async runtimes. A profiler that only sees OS threads can’t tell which task was running.

So does every method need to carry the span id? No. The span id already travels with the virtual thread, inside the OpenTelemetry context. The data is right there. The profiler just reads it from the wrong place. There are two real fixes.

1. Swap the tag on every switch. When a virtual thread mounts, copy its span id into the carrier’s slot. When it unmounts, clear it. The sampler stays the same. Catch: the JVM doesn’t give normal Java code a mount callback, so a profiler has to hook JVM internals. It also adds a little work to every park and resume, and those happen constantly.

2. Read the task at sample time. When the timer fires, find which virtual thread is mounted and read its context. Zero cost on the switch path. But it’s hard to do from a signal handler, where you’re reading Java objects the garbage collector might be moving. It really wants a profiler built into the runtime.

Coroutines are a library, so the switch point is out in the open. A ThreadContextElement gets a callback every time a coroutine resumes on a thread and every time it suspends. OpenTelemetry already uses it to keep its own context right across coroutines. Same idea for the profiler’s tag:

// Sketch: tag the thread on resume, clear it on suspend. class ProfilerTag(private val spanId: Long) : ThreadContextElement<Unit> { companion object Key : CoroutineContext.Key<ProfilerTag> override val key = Key override fun updateThreadContext(context: CoroutineContext) = profiler.tag(spanId) override fun restoreThreadContext(context: CoroutineContext, oldState: Unit) = profiler.clear() }

So coroutines could solve it, but nothing does it for you yet, as far as I know. OpenTelemetry’s coroutine support only carries its own context, and the profiler doesn’t ship an element like this one. For now you’d write it yourself.

That’s fix 1 in user space. Virtual threads need the exact same hook. The JDK keeps it internal.

In Go, the profiler is part of the runtime, so labels live on the goroutine, not the OS thread:

pprof.Do(ctx, pprof.Labels("span_id", spanID), func(ctx context.Context) { handle(ctx) })

When the CPU profiler’s signal fires, it reads the labels of whichever goroutine is running right then. A goroutine can move between OS threads; its labels come along. No hooks, no swapping. That’s fix 2, and it’s cheap because the scheduler and the profiler are the same runtime. New goroutines inherit their parent’s labels too.

pprof supports tagging out of the box, and it gets M:N right because one runtime owns both the scheduler and the profiler. On the JVM, profilers sit outside the scheduler and need a hook