Orbit C++ → Rust · Post 20

One Lost Return, Ten Thousand Ghosts

A hooked function kept appearing nested inside itself, tens of thousands of times. The first theory was a kernel that duplicates uprobe hits on thread migration. It was wrong, and so was the second theory, and the mistake that produced the second one is the most useful part of the story. The real cause is one lost return per thread, at the instant instrumentation is switched on, turned into a landslide by pairing entries to returns by counting them.

73,944Entry hits the kernel delivered, one capture
73,894Return hits — 50 fewer, all accounted for
6Threads that lost a return, each at its very first call
16,174Ghost scopes those six losses became, paired by count
0Ghosts once paired by stack frame

Hook four Box3D functions with kernel uprobes, run the physics on more threads than the machine has cores, and the timeline fills with scopes that cannot be right. b3World_Step, the outermost call, appears nested inside another b3World_Step, and inside that one another, on some threads a couple of levels deep and never coming back up. The function calls no copy of itself. Something is wrong, and the profiler is stating it with a straight face, complete with durations and a call tree.

See it

Two captures of the same workload, four functions hooked. The only difference is one switch. Open a thread in each and read the depth of b3World_Step: in the first it is often one or two levels down, a scope inside a scope of the same name; in the second it is always at the top, where it belongs.

Paired by count — ghosts

Around 40% of b3World_Step scopes sit below depth 0, on the threads that lost a return. The sampling report on the right is correct; only the instrumented scopes are wrong.

Paired by frame — clean

Same workload, same four hooks, one switch flipped. Every b3World_Step at depth 0.

These are the real capture frames a connecting viewer would receive, opened with no service behind them. Dynamic instrumentation is what makes the bug visible at all: a sampling profiler counts a miscounted call as a rounding error, but instrumentation draws every call as a box at the depth it ran, so one accounting mistake is a box in the wrong place, and it stays there for the eye to catch.

The theory everyone starts with

C++ Orbit has a workaround for this exact symptom. Its UprobesUnwindingVisitor keeps, per thread, the stack pointer, instruction pointer and CPU of the last uprobe, and drops an incoming entry that repeats the last one's sp and ip from a different CPU, under a comment that reads, in part, “on thread migration, uprobe events can sometimes be duplicated.” Orbit opens its probes per CPU, so one hit surfacing in two CPUs' ring buffers is plausible, and the fix has worked for years. The rule was ported to the Rust service line for line. On the ghost capture it dropped nothing — not a few, zero — and every run since reports the same: filter off, 0 migration duplicates went through. Whatever this was, it was not a duplicated stack pointer.

The mistake worth telling

The service can write every probe hit to a file before any pairing (--uprobe-dump): timestamp, thread, CPU, function, entry or return, and the stack pointer and instruction pointer the sample carries. I walked a thread's hits keeping a stack of open frames by their stack pointer, flagged every break in the nesting, and found losses everywhere — hundreds of them, entries and returns, and a first draft of this post that said the kernel loses about one hit in ten, correlated with thread migration.

That draft was wrong, and it was wrong for a dull reason. The dump is written in the order the per-CPU rings are drained, not the order the hits happened. A thread's entry and the return of the call before it can come off two different CPU rings microseconds apart and land in the file out of order. The service does not pair them in that order — it holds hits for 100 ms and sorts them by timestamp first — but my analysis did not, so it saw phantom breaks in the nesting wherever the file order and the true order disagreed. One line, sorting each thread's hits by timestamp before the walk, deleted about 500 of the 513 anomalies. The 258 “lost entries” became zero. The correlation with migration went with them.

What the sorted hits say

Sorted, the same 73,944-entry capture is almost perfectly balanced: 73,944 entries, 73,894 returns. The 50-hit gap is functions still running when the capture stopped. The genuine anomalies mid-capture number eight, in six threads, and they share a property the file order had hidden:

entries delivered            73,944
returns delivered            73,894     (50 open at capture end)
anomalies, timestamp-sorted       8     (all lost returns)
  ...their position         first 1% of each thread's hits
kernel duplicates                 0

Every one of the eight is a lost return, and every one is at the very start of its thread. Two consecutive b3World_Step entries appear at the same stack pointer, on the same CPU, milliseconds apart, with no return between them: the first call's return never arrived. There are no duplicates, on this box, at all.

How six losses become sixteen thousand ghosts

Eight lost returns cannot draw sixteen thousand ghost boxes on their own. The multiplier is the pairing. With the filter off, entries and returns are matched by counting: an entry pushes a level, a return pops one. That has no way to notice a missing return. Drop one, and the entry it belonged to never closes; the next call opens inside it, and the one after that inside that, and every scope on the thread is a level too deep for the rest of the capture. Simulating count-based pairing on the raw hits reproduces the bundle exactly — 16,187 ghosts against the capture's 16,174 — and it makes no difference whether the hits are fed in file order or timestamp order. Six threads that each lost their first return account for all of it.

Frame-based pairing does not count; it reads the stack pointer every hit carries. A nested call sits strictly below its caller's frame, and a return leaves exactly the frame its entry opened. So an entry that lands at or above a frame still marked open proves that frame's return was lost: the stale frame is closed, and the new call opens at the right depth. On the same raw hits, in either order, this gives zero ghosts. It is the same idea the C++ visitor uses; its rule fires on the missing-return case, which its own comment names first (“MISSING URETPROBE OR DUPLICATE UPROBE”), and the migration-duplicate reading was always the second half of an or.

Why a return goes missing, and why at the start

A uretprobe is not a breakpoint at the return address; it is a hijack. When the entry fires, the kernel rewrites the return address on the user stack to point at a trampoline. Instrument a process that is already running and its threads are mid-loop, and the first call caught after the probes arm does not get a clean hijack — its return goes to the real address, not the trampoline, and no return event is produced. That is not a kernel bug. It is the unavoidable edge of switching instrumentation on over a running program, and it shows up exactly where the data puts it: the first call of each affected thread.

The proof is one line of the previous post's stress test. That test arms the probes and then starts its worker threads, so no call is ever in flight when a probe lands, and it records 720,000 scopes in a second with nothing lost and nothing at the wrong depth. Box3D loses a handful of returns because it is already looping when we hook it. Same hooks, same kernel; the only difference is whether a call was in flight at the moment of arming.

What is proven

The kernel is not losing hits at any meaningful rate: entries and returns balance to a hundredth of a percent, and there are no duplicates. The ghosts are a handful of returns lost at the arming edge, each one turned into a thread-long landslide by pairing that counts instead of looking at the frame. Pairing by the stack pointer bounds each loss to the single scope it actually damaged and gets every other depth right, which is the 40%-to-nothing the two captures show. The migration duplicate the C++ code guards against did not appear once here; the guard costs nothing and stays, in case a kernel ever does double, but it is not what was wrong. And the first version of this post, which blamed the kernel for losses it never made, was an artifact of reading hits in the order they were drained rather than the order they occurred — a good reminder that the fix for a profiler bug can start with a bug in how you read the profile.