backtrace: unwind the interrupted thread when sampling from an interrupt

[gburd]

The sampling profiler (core/sampler.cc) fires from a timer interrupt and logs a
backtrace via tracepoint_base::do_log_backtrace(), which calls
backtrace_safe(). That walks the frame-pointer chain of the caller, which in
interrupt context is the interrupt handler, not the thread that was interrupted.

The handler's chain cannot cross back into the interrupted thread: the entry stub
pushes an exception_frame, not a frame record, so there is no link for an
unwinder to follow. The walk terminates in the interrupt-entry frames and every
sample is attributed to them.

The effect is that the profiler reports the same handful of addresses for every
sample regardless of what the guest is doing, which makes it useless for
attribution.

The fix

Add backtrace_safe_from_interrupt(), which uses current_interrupt_frame (an
existing per-thread pointer, set for the duration of interrupt() and null
elsewhere) to unwind the interrupted thread:

• pc[0] is the saved rip/elr from the exception frame. That is the
  instruction that was executing when the interrupt arrived, so it needs no
  unwinding at all and is correct even where the interrupted code was built
  without frame pointers.
• the rest of the walk follows the interrupted thread's own frame-pointer chain,
  from ef->rbp (x64) / ef->regs[29] (aarch64).

current_interrupt_frame being null outside interrupt context is what makes this
safe: the new function then falls back to backtrace_safe() and is
byte-for-byte equivalent to the old behaviour. Only do_log_backtrace() is
switched over, so nothing outside tracing changes.

Both architectures are implemented. The existing fp-walk loop is factored into
unwind_fp_chain() and shared, so the two entry points cannot drift apart. The
x64 loop also gains a null check on the starting rbp, which the aarch64 one
already had.

Effect

Measured on an otherwise identical image and workload, over the same 954k
samples: distinct program counters at frame 0 went from 1 to 2048. Before
the change every sample landed on one address; after it the profile has real
spread.

Verification, since this repo has no CI (these are my own runs)

check	result
builds from scratch, x86_64	yes. make build/release.x64/loader.elf in a fresh output dir: 1370-line log, LINK loader.elf, LIBOSV.SO, 0 errors, 70 MB loader.elf. The log shows CXX arch/x64/backtrace.cc, CXX core/trace.cc and CXX core/mmu.cc, so the files this patch changes were actually compiled and this is not an incremental relink.
builds, aarch64	yes. ARCH=aarch64 CROSS_PREFIX=aarch64-unknown-linux-gnu- build/release.aarch64/arch/aarch64/backtrace.o, 0 errors, 0 warnings.
the change is live, not a no-op	object A/B against a build of pure master at the same commit: arch/x64/backtrace.o md5 5f7aecf0 -> c24a697c, core/trace.o 1fec544b -> 4e0597f1, arch/aarch64/backtrace.o 1f909eed -> 2da2bd3c.
the new entry point exists in the object	nm on both arches shows backtrace_safe_from_interrupt(void**, int) in the patched object and absent from the master build, alongside the unchanged backtrace_safe.
merges clean	git merge-tree --write-tree --messages upstream/master <branch> run from a worktree checked out at master: 0 conflicts.
API it depends on is upstream	current_interrupt_frame is on master today for both arches: arch/x64/exceptions.cc:26,259,264 + exceptions.hh:49, and arch/aarch64/exceptions.cc:21,227,234 + exceptions.hh:37. Set in interrupt() and nulled on the way out.
signed	single commit, %G? == G.

One note for anyone reproducing the x86_64 build on a fresh tree: it fails at
bootfs.bin with FileNotFoundError: libsolaris.so before reaching the link.
That is unrelated to this patch, reproduces on pure master, and is what #1514
fixes; I stacked #1514 locally to get the full link above. This patch itself
touches no build file.

[nyh]

I'll let my AI do the review because it does it so well. of course, I'm only pasting here things I agree with, I'm not doing this automatically. I'm not 100% convinced of its proposal about the tracing option - but the other things do appear solid objections.

The problem is real, but the explanation in the commit message is wrong, and the fix is applied too broadly.

The stated mechanism is incorrect:

The PR's central claim — "the handler's chain cannot cross back into the interrupted thread… there is no link for an unwinder to follow… the walk simply terminates in the entry frames" — does not hold on either architecture.

On x86-64, entry.S line 28, pushes %rbp as part of the register save, but never clobbers it before call \handler (only r14/r12/r13/rax/rdx/rcx/rdi/rsp are touched). And interrupt() is compiled with -fno-omit-frame-pointer (Makefile:361). Disassembling a built build/release.x64/loader.elf confirms it:

000000004030cfb0 <interrupt>:
    4030cfb0:  55           push   %rbp
    4030cfb1:  48 89 e5     mov    %rsp,%rbp

So interrupt()'s frame record is {saved rbp = the interrupted code's rbp, return address = inside interrupt_entry_common}. The chain does link back into the interrupted stack. aarch64 is the same — push_state_to_exception_frame saves x29 but doesn't modify it before bl.

This isn't just my reading; OSv's own tooling depends on it. scripts/osv/prof.py:73-84 lists the sampler's expected prefix and it ends with:

'interrupt_descriptor_table::invoke_interrupt(unsigned int)',
'interrupt',
'interrupt_entry_common'),

i.e. the profiler strips those twelve frames and expects real workload frames after them.

But there is a real bug, with a different cause:

That prefix list is 12 entries and tracepoint_base::backtrace_len is 10 (trace.hh:307). So:

• strip_garbage()'s len(backtrace) >= len(chain) test is never true — the strip never fires, and every sampler stack is 10 frames of tracing + interrupt machinery. That matches the "every sample attributed to the interrupt-entry frames" observation exactly.
• Separately, and independently worth fixing: the leaf pc — the instruction actually executing — is never recorded at all, even with a longer buffer. A frame-pointer walk from the handler can only ever give you the interrupted function's callers.

So I agree the sampler is broken and that recording ef->rip/ef->elr is the right thing to do (it's what perf does). The commit message just needs to say why correctly.

The evidence offered doesn't support the conclusion:

"Distinct program counters at frame 0 went from 1 to 2048" proves almost nothing. Frame 0 of backtrace_safe() is, by construction, the return address into do_log_backtrace() — a single static call site, for every tracepoint, in or out of interrupt context. It was always going to be 1. What would actually demonstrate the fix is trace.py prof output before/after showing frames that resolve to workload symbols. (2048 is also a suspiciously round number for a distinct-address count.)

The change is too broad — this is my main objection:
do_log_backtrace() serves every tracepoint, and --log-backtrace turns backtraces on globally for all of them (loader.cc:844→ core/trace.cc:189). After this patch, any tracepoint that fires inside an interrupt handler — virtio/net rx, timer, an allocation on the rx path — logs the stack of some unrelated interrupted thread instead of the call path that reached the tracepoint. That is precisely the opposite of what --log-backtrace is for. trace.py memory_analyzer, which attributes allocations by backtrace, would silently misattribute anything allocated in interrupt context.

The right shape is to make it opt-in: a per-tracepoint flag (set by core/sampler.cc next to trace_sampler_tick.backtrace(true)) that selects the interrupt-aware walk, leaving every other tracepoint on backtrace_safe(). The new function itself is fine — it's the wiring in core/trace.cc:368 that shouldn't be unconditional.

Smaller points:

• "byte-for-byte equivalent" outside interrupt context is compiler-dependent. return backtrace_safe(pc, nr); is only equivalent if GCC emits a sibling call. If it ever doesn't, an extra frame appears at pc[0], shifting everything by one and breaking prof.py's prefix chains. Worth making deterministic rather than relying on -O2 behavior.
• static inline unwind_fp_chain() has a latent hazard. backtrace_safe() captures its own %rbp, then passes it to a function that, if not inlined, builds its own frame over the frame being read. It will inline at -O2, but __attribute__((always_inline)) would make that a guarantee rather than a hope.
• ef->rip / ef->rbp are plain loads in a file whose entire premise is safe_load. current_interrupt_frame is __thread, and this patch is the first code to read it from outside interrupt() — i.e. from arbitrary tracepoint context, where fsbase may be an app TCB (tls-switch.hh) and the kernel TLS slot is a different piece of memory. The window is narrow, but a non-null garbage ef faults on an unguarded ef->rip. Either safe_load it, or note that this state is really per-CPU (interrupts don't nest and don't migrate) and belongs in the %gs percpu area.
• prof.py isn't updated. With the fix, sampler stacks have no machinery prefix at all, so unimportant_prefixes[0] becomes dead and misleading. Nothing breaks, but the tooling should move with the kernel.
• The x64 null-rbp check is redundant (safe_load already handles a faulting address via the fault fixup) — harmless, just not the improvement the description implies.
• aarch64 regs[29] and elr check out against the struct and the push order in push_state_to_exception_frame (x29 at +232, x30 at +240, elr at +256).

What I'd ask for before merging:

Rewrite the commit message around the actual cause (12-frame machinery prefix vs backtrace_len = 10, plus the missing leaf pc), make the new walk opt-in per tracepoint so --log-backtrace doesn't regress, and replace the frame-0 statistic with a before/after trace.py prof. Consider bumping backtrace_len and updating prof.py in the same series. The core idea — take pc[0] from the exception frame — is sound and worth having.

[gburd]

You are right on every point, including the one I would have defended. Thank you for the depth here, and please pass on my thanks to your AI for the entry.S and Makefile work - those were two-minute greps I should have done before writing a mechanism.

The stated mechanism is wrong. I verified it in-tree rather than take it on faith:

• arch/x64/entry.S pushes %rbp in the register save and never clobbers it before call \handler, only the arg registers and r12/r13/r14.
• Makefile:398 builds the kernel with -fno-omit-frame-pointer.

So rbp on entry to interrupt() still points into the interrupted thread's frame, the chain is not severed, and an rbp walk can cross back. My "there is no link for an unwinder to follow" is simply false, and a wrong mechanism in a commit message is worse than none, because the next reader believes it.

Your root cause is the right one, and it is checkable: tracepoint_base::backtrace_len is 10 (trace.hh:307) while prof.py's unimportant_prefixes chain is 13 entries, so strip_garbage()'s len(backtrace) >= len(chain) test can never be true. The strip never fires and every sampler stack is machinery. That explains the observation exactly, and it explains it without needing my story. Plus the separate point that a frame-pointer walk from the handler can only ever give the interrupted function's callers, never the leaf pc - which is why taking ef->rip is the right fix for a reason I got to by luck rather than by analysis.

The frame-0 statistic does not support what I claimed. You are right that frame 0 of backtrace_safe() is the return address into do_log_backtrace(), a single static call site, so it was always going to be 1. "1 to 2048" measures the change in what the function returns, not that the result is now correct. (And 2048 being a round number is the table capacity, which makes it worse evidence, not better.) I will replace it with before/after trace.py prof output showing frames resolving to workload symbols.

Your main objection is the one I most needed and completely missed. do_log_backtrace() serves every tracepoint and --log-backtrace is global, so as written any tracepoint firing inside an interrupt handler logs an unrelated interrupted thread's stack instead of the path that reached it - the exact opposite of the option's purpose, and a silent misattribution for memory_analyzer. Making it opt-in per tracepoint, set next to trace_sampler_tick.backtrace(true) in core/sampler.cc, is clearly the right shape. The new function is not the problem; the unconditional wiring is.

I will respin the series as:

1. commit message rewritten around the real cause: the 12/13-entry machinery prefix versus backtrace_len = 10, plus the missing leaf pc;
2. the interrupt-aware walk made opt-in per tracepoint, leaving every other tracepoint on backtrace_safe();
3. the frame-0 statistic replaced with before/after trace.py prof showing real workload symbols;
4. __attribute__((always_inline)) on unwind_fp_chain so inlining is guaranteed rather than hoped for, and the tail call made deterministic instead of relying on -O2 emitting a sibling call;
5. ef->rip/ef->rbp guarded. On your suggestion I will look at moving this state to the %gs percpu area rather than __thread, since interrupts do not nest and do not migrate, which makes it per-CPU by nature - if that turns out to be more than a small change I will safe_load it in this series and do the move separately;
6. prof.py updated alongside, and I will look at backtrace_len in the same series since a 10-frame buffer is marginal either way.

On the tracing-option proposal you were not fully convinced by: your instinct is right to be cautious, and the version I will send makes it opt-in per tracepoint rather than adding any new user-visible option, so --log-backtrace keeps its current meaning exactly. If you would rather see the commit-message fix and the opt-in wiring alone, with backtrace_len and prof.py as a follow-up, say so and I will split it that way.

[gburd]

Respin is written but not yet pushed to this PR, because I cannot build it on this host and I am not going to ask you to look at an unbuilt claim. It is on wip/respin-1515-unbuilt if you want to read it early; I will force-push it here once it has compiled on a machine that can.

What it does, against your list:

Opt-in per tracepoint. tracepoint_base gets an interrupt_backtrace(bool) setter and a _interrupt_backtrace flag defaulting false. do_log_backtrace() selects the walk on that flag, so --log-backtrace keeps its exact current meaning for every tracepoint; core/sampler.cc opts in next to trace_sampler_tick.backtrace(true). You were right that the function was fine and the wiring was the problem.

Commit message rewritten around the real cause. It now leads with the two independent reasons a sampler stack is unusable: the leaf is missing, because a frame-pointer walk can only ever recover callers; and nothing is ever stripped, because prof.py's prefix chain is 13 entries while backtrace_len is 10, so strip_garbage()'s len(backtrace) >= len(chain) test can never be true. The severed-chain story is gone entirely, along with the frame-0 statistic. I also dropped the "byte-for-byte equivalent" claim rather than defend it.

safe_load on the exception-frame reads, both arches, with your reasoning in the comment: current_interrupt_frame is __thread, this is the first code to read it from outside interrupt(), and fsbase may point at an app TCB there. A failed rip/elr load returns 0; a failed rbp/x29 load returns 1, keeping the leaf we already have.

__attribute__((always_inline)) on unwind_fp_chain, both arches, so the inlining is a guarantee.

Still owed, and I would rather land the above first and do these as a follow-up than bundle them: prof.py updated for the no-prefix case, backtrace_len reconsidered, and the before/after trace.py prof output that should have been the evidence in the first place. On the %gs percpu suggestion, I think you are right that this state is per-CPU by nature, but it is a bigger change than the rest and I would rather it be its own patch than hide inside this one.

One thing worth saying plainly: the fix was right for a reason I had not worked out. I wrote a mechanism that sounded plausible, did not check entry.S or Makefile:398, and offered a statistic that could not have distinguished the hypotheses. Both were two-minute checks. Thank you for doing them.

[gburd]

Pushed as 437460f74. It builds now, so the respin is on the PR rather than sitting on a side branch.

Build: full make from a clean tree, 1170 compile steps, LINK loader.elf, exit 0, no warnings on the changed files. nm -C on the object shows backtrace_safe_from_interrupt(void**, int) present, and core/trace.o references both walks, which is what opt-in should look like. There is exactly one opt-in site in the tree:

core/sampler.cc:162:    trace_sampler_tick.interrupt_backtrace(true);
include/osv/trace.hh:316:    bool _interrupt_backtrace = false;

so every other tracepoint keeps backtrace_safe() and --log-backtrace is unchanged.

Two things worth reporting from doing this properly.

Your #1514 is confirmed by accident, on a third machine. My first full build failed at

File "scripts/mkbootfs.py", line 63, in main
FileNotFoundError: [Errno 2] No such file or directory: 'libsolaris.so'
make: *** [Makefile:2239: build/release.x64/bootfs.bin] Error 1

which is exactly the bug #1514 fixes, reproduced on a bare make with fs unset and none of my patches involved. Applying #1514 to the same tree took it from that failure to exit 0. So that one is not a theoretical dependency gap - the kernel does not build without it on a fresh checkout.

The build needed two musl submodules, not one. libc/locale/*.c symlink into musl_0.9.12 while the rest of the tree uses musl_1.2.1, and git submodule update --init silently does nothing for either unless --force is passed. That is what had blocked me from building this locally before, and it is worth knowing if anyone else reports "no rule to make target libc/locale/catopen.c" - the file is there, the symlink target is not.

Still owed, as follow-ups rather than in this PR: prof.py updated for the no-prefix case, backtrace_len reconsidered, the before/after trace.py prof output, and the %gs percpu move for current_interrupt_frame. I would rather land the corrected mechanism and the opt-in wiring first and do those separately, but say the word if you want any of them folded in.

[gburd]

I have to correct something, and it is in my commit message rather than yours: the root cause we settled on is not right, and the reason the patch helps is narrower than either of us wrote.

I built the unpatched kernel and measured the strip. Chain 0 matches 16410 of 16411 unpatched sampler records, 100.0%. So the strip fires. The 12 > 10 inference is void because strip_garbage() does not compare against the 10 raw pcs: scripts/trace.py:104 resolves with show_inline=not args.no_inlined_by, so inlining is on by default and 10 pcs expand to 16-24 frames. A 12-entry chain against a 20-frame list matches fine.

And the unpatched sampler was not producing machinery. After stripping it attributes 97.48% to the workload's outer_workload/main. So "the sampler is broken, now it works" is false and I am dropping it.

The real defect is leaf attribution, which is what your finding 2 predicted. One line of evidence:

BEFORE: 0 pcs inside inner_hash        (the actual hot leaf: never sampled, not once)
AFTER:  4 distinct pcs inside it, 90.5% of samples

A frame-pointer walk yields callers only - your words - so the leaf was structurally unreachable, and ef->rip reaches it. Your instinct was right even though the arithmetic supporting it was not. That before/after is also the evidence you asked for in place of my frame-0 statistic, which I agree proves nothing: frame 0 unpatched is a single static call site and was always going to be 1.

I am not touching prof.py after all, and I measured why not. I removed chain 0 on the theory it had become vestigial, then tested reading a stock-kernel trace with the edited script: prof.py is not versioned with the kernel, so the removal re-exposes six frames of machinery at the root of every profile from any pre-patch trace file. Reverted. If the patched sampler no longer needs that chain, the right change is to stop applying it to sampler records specifically, not to delete a list that older traces still need - and that is a separate patch.

Two smaller corrections while I am at it. Chains 1 and 2 matched 0% on both traces, so my earlier claim that other tracepoints rely on them is unverified and I withdraw it. And backtrace_len: with the chain at 12 rather than something longer, the "10 is marginal" argument loses its support, so I am leaving it alone unless there is an independent reason.

Item D, the %gs move: no, and it is closed rather than deferred. entry.S:38-60 fetches the kernel TCB from %gs:16 and switches fsbase before any handler runs, so the app-TCB hazard is not live. And include/osv/percpu.hh:14 is extern __thread char* percpu_base, so PERCPU() is itself a __thread access - the move would not remove the access it was meant to remove. The safe_load guards stay.

What I got wrong on my side is worth stating plainly, because you caught me doing it once already in this review. I verified your operands and not your operation: I checked that backtrace_len really is 10 and that a prefix list really exists, found both true, and accepted the inference joining them without counting the entries. Then I compounded it by recounting from an already-edited working tree and getting 6-and-5, which is the post-edit state. Three readings of one number, none of them against the pristine file.

Four of your five findings stand unchanged and the patch is better for all of them. I will push the rewritten commit message shortly.