From 397b881e0ca07931b61cb92d5ecb3246877cae74 Mon Sep 17 00:00:00 2001 From: sotashimozono Date: Mon, 7 Sep 2026 13:13:20 +0000 Subject: [PATCH] fix: record lost a mark born during the block, and the backtrace of what threw MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two defects in `record`, both found by reviewing #24 and both older than it. The first breaks the one thing the default layer promises. **A mark that came into existence WHILE the block ran was lost — from the always-on layer too.** `record` snapshotted the probe set before calling `f` and never looked again, so a probe born during the call was entered by code that ran, counted by nobody, and left with its flag `false` for the rest of the process. `entered()` and the exit summary never learned about it either, because while a recording is open the write side counts into the probe instead of setting the flag, and only `record`'s epilogue sets it — over the stale snapshot. record saw: [:tracked] entered(D) = [:tracked] …after: [:newborn, :tracked] entered(D) = [:newborn, :tracked] A package extension loaded inside the block is the ordinary way this happens, and this package ships three of them. The probe set is now re-derived after the call, `saved` is keyed by probe rather than by position, and the reconciliation runs over the union. Re-deriving needs `invokelatest`: the new probes' bindings are younger than the frame reading them, and 1.12 warns that will become an error. **The exception's backtrace pointed at `record`, not at the caller.** `throw(err)` after the `catch` block manufactures a fresh backtrace, so a user debugging a failed run saw `record.jl` and macro expansion where `outer → mid → deep → energy` should be, with nothing to say frames had been dropped — in exactly the case `record(f; rethrow = false)`'s own docstring names as the reason to use it. Closing now happens inside the `catch` and the exception is re-raised with `rethrow()`, which keeps the backtrace it arrived with. The old comment claiming this was impossible was wrong: it is impossible *after* the catch, which is where the call had drifted to. Both are pinned by tests that fail against the unfixed file, each with a control — a mark defined and never called is still absent, and the direct call is shown to carry the frames the recorded one must also carry. Co-Authored-By: Claude Opus 5 --- src/record.jl | 75 ++++++++++++++++++++++++---------- test/spec/README.md | 4 +- test/spec/test_spec_profile.jl | 62 ++++++++++++++++++++++++++++ 3 files changed, 118 insertions(+), 23 deletions(-) diff --git a/src/record.jl b/src/record.jl index f59c516..0d7fdba 100644 --- a/src/record.jl +++ b/src/record.jl @@ -215,11 +215,13 @@ function record( ps = probes() slots = Threads.maxthreadid() sampled = false - saved = Bool[] + # Keyed by probe rather than by position: the set is re-derived after the block, and a + # positional `saved` cannot be lined up against a set that grew. + saved = Dict{Probe,Bool}() @lock _RECORD_LOCK begin if _DEPTH[] == 0 - saved = Bool[p.entered for p in ps] for p in ps + saved[p] = p.entered _arm!(p, slots) p.entered = false end @@ -236,36 +238,67 @@ function record( if timing && outermost sampled = start_timing!(timing_backend(); clear=(!with_profile)) end + + counts = Dict{Probe,Int}() + measured = Probe[] + closed = Ref(false) + # Closing is a closure because it has to run on two paths, and on the failing one it has to + # run INSIDE the `catch` — see the call site. + function close!() + closed[] && return nothing + closed[] = true + sampled && stop_timing!(timing_backend()) + # The probe set is re-derived here rather than reused from before the call. A mark can + # come into existence WHILE the block runs — a package extension loaded by `f` is the + # ordinary way — and a probe that was not in the snapshot is entered by code that ran, + # counted by nobody, and left with its flag `false` for the rest of the process. That + # loses the entry from `entered()` and from the exit summary too, which is the one thing + # the default layer promises never to do. + # + # `invokelatest`, because reading those probes is the whole point and their bindings are + # younger than this frame: `probes()` reaches `M.__EXPERIMENTAL_API_ENTERED_newborn__`, + # created while `f` ran. Julia 1.12 warns that reading a binding in a world prior to its + # definition world will be an error. + append!(measured, Base.invokelatest(probes)) + for p in measured + counts[p] = _probe_count(p) - get(before, p, 0) + end + @lock _RECORD_LOCK begin + _DEPTH[] -= 1 + if _DEPTH[] == 0 + _RECORDING[] = false + _CAPTURE_PATHS[] = true + for p in measured + p.entered = get(saved, p, false) || counts[p] > 0 + end + end + end + return nothing + end + t0 = time() err = nothing try f() catch e err = e + if rethrow + # Closed here, and re-raised from inside the `catch`, because that is the only place + # the exception's own backtrace survives. Closing first and calling `throw(err)` + # afterwards — which is what this did — manufactures a fresh backtrace rooted in this + # function, so the caller debugging a failed run sees `record.jl` where their own call + # chain should be. + close!() + Base.rethrow() + end end elapsed = time() - t0 - sampled && stop_timing!(timing_backend()) + close!() times = sampled ? attribute_timing(timing_backend()) : nothing - - counts = Dict{Probe,Int}(p => _probe_count(p) - get(before, p, 0) for p in ps) - traces = Dict{Probe,Vector{Vector{Symbol}}}(p => _paths_of(p) for p in ps) - @lock _RECORD_LOCK begin - _DEPTH[] -= 1 - if _DEPTH[] == 0 - _RECORDING[] = false - _CAPTURE_PATHS[] = true - for (i, p) in enumerate(ps) - p.entered = (i <= length(saved) && saved[i]) || counts[p] > 0 - end - end - end - # `Base.rethrow(err)` is legal only inside a `catch`; here it raises - # "rethrow(exc) not allowed outside a catch block" and the caller never sees their own - # exception. `throw` gives a fresh backtrace, which is the price of building the record first. - err === nothing || rethrow && throw(err) + traces = Dict{Probe,Vector{Vector{Symbol}}}(p => _paths_of(p) for p in measured) hits = Hit[] - for p in ps + for p in measured n = counts[p] n > 0 || continue mk = mark(p.mod, p.name) diff --git a/test/spec/README.md b/test/spec/README.md index d3bce0e..ef39068 100644 --- a/test/spec/README.md +++ b/test/spec/README.md @@ -52,10 +52,10 @@ that is entirely `@test_broken` is a claim written down, not a check being run. | `test_spec_forms.jl` | 24 | 24 | 0 | the definition forms a real package hits on its second afternoon | | `test_spec_integration.jl` | 19 | 19 | 0 | where the mark has to surface: docs, Aqua, releases, provenance, CI | | `test_spec_lifecycle.jl` | 16 | 16 | 0 | the mark's EXIT, and an entry point that is a module rather than a function | -| `test_spec_profile.jl` | 43 | 43 | 0 | what a real run went through, how often, and how much of it | +| `test_spec_profile.jl` | 45 | 45 | 0 | what a real run went through, how often, and how much of it | | `test_spec_propagate.jl` | 20 | 20 | 0 | a caller that never names a marked thing still depends on it | | `test_spec_verify.jl` | 9 | 9 | 0 | how well is a marked thing exercised by the tests | -| **10 files** | **180** | **180** | **0** | | +| **10 files** | **182** | **182** | **0** | | The table is generated and pinned by `test/test_spec_table.jl`, which fails if it goes stale — diff --git a/test/spec/test_spec_profile.jl b/test/spec/test_spec_profile.jl index 8c99583..6cfd773 100644 --- a/test/spec/test_spec_profile.jl +++ b/test/spec/test_spec_profile.jl @@ -370,6 +370,68 @@ end @test 0.0 <= r.overhead <= 1.0 end +@testset "a mark born while the block runs is measured, not lost" begin + # The probe set was snapshotted BEFORE the call and never re-derived, so a mark that came + # into existence while `f` ran was entered by code that ran, counted by nobody, and left with + # its flag `false` for the rest of the process. That loses the entry from the OPT-IN layer and + # from the always-on one — `entered()` and the exit summary — which is the one thing the + # default layer promises never to do. + # + # A package extension loaded inside the block is the ordinary way this happens, and this + # package ships three of them; `Core.eval` is the same event without the loading machinery. + @eval module Newborn + using ExperimentalAPI + public settled_mark + @experimental "present before the block" settled_mark(x) = x + 1 + end + r = ExperimentalAPI.record() do + Base.invokelatest(Main.Newborn.settled_mark, 1) + Core.eval(Main.Newborn, :(@experimental "born mid-call" newborn(x) = x * 2)) + Base.invokelatest(Base.invokelatest(getglobal, Main.Newborn, :newborn), 2) + end + @test :newborn in [h.name for h in r] + @test :settled_mark in [h.name for h in r] + # The always-on layer, which never asked to be turned on and cannot be turned off. + entered = [e.name for e in ExperimentalAPI.entered(Main.Newborn)] + @test :newborn in entered + @test :settled_mark in entered + # Control: a mark defined but never called is still absent, so the fix did not simply start + # reporting everything it can see. + Core.eval(Main.Newborn, :(@experimental "born and never called" stillborn(x) = x)) + @test :stillborn ∉ [h.name for h in r] + @test :stillborn ∉ [e.name for e in ExperimentalAPI.entered(Main.Newborn)] +end + +@testset "an exception keeps the backtrace that points at the caller's own code" begin + # `record` caught the exception, did its bookkeeping, then re-raised with `throw(err)` — which + # outside a `catch` manufactures a FRESH backtrace rooted in `record`. The caller debugging a + # failed run saw `record.jl` and macro expansion where their own call chain should be, with + # nothing to say frames had been dropped. + @eval module Boom + using ExperimentalAPI + public energy + @experimental "why" energy(x) = x < 0 ? error("boom") : x + end + deep(x) = Main.Boom.energy(x) + mid(x) = deep(x) + outer(x) = mid(x) + frames(f) = + try + f() + String[] + catch + [string(fr.func) for fr in stacktrace(catch_backtrace())] + end + + own = ["outer", "mid", "deep", "energy"] + direct = frames(() -> outer(-3)) + @test all(n -> n in direct, own) # the fixture can disagree + viarecord = frames(() -> ExperimentalAPI.record(() -> outer(-3))) + @test all(n -> n in viarecord, own) + # …and the exception itself is still the caller's, not a wrapper. + @test_throws ErrorException ExperimentalAPI.record(() -> outer(-3)) +end + @testset "recording nests without double counting" begin @test ExperimentalAPI.record(() -> ExperimentalAPI.record(() -> Sim.driver(M, 10)))[1].count == 10