From 397b881e0ca07931b61cb92d5ecb3246877cae74 Mon Sep 17 00:00:00 2001 From: sotashimozono Date: Mon, 7 Sep 2026 13:13:20 +0000 Subject: [PATCH 1/3] 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 From bac48b70015f13b6a21990147b137d3e0855966f Mon Sep 17 00:00:00 2001 From: sotashimozono Date: Mon, 7 Sep 2026 13:18:33 +0000 Subject: [PATCH 2/3] wip: @entered carries the value; report and test gaps --- src/macros.jl | 107 ++++++++++++++++++++++++++++++-------------- src/record.jl | 18 ++++++-- test/test_macros.jl | 75 ++++++++++++++++++++++++++++++- 3 files changed, 161 insertions(+), 39 deletions(-) diff --git a/src/macros.jl b/src/macros.jl index b2a1434..11f7c3e 100644 --- a/src/macros.jl +++ b/src/macros.jl @@ -15,12 +15,15 @@ The question [`entered`](@ref) answers about a whole process, asked about one ca ```julia julia> ExperimentalAPI.@entered sweep(model; βs = 0.05:0.05:2.0) ┌ @entered sweep(model; βs = 0.05:0.05:2.0) at sweep.jl:42 -│ MyPkg.energy ×10000 — convergence not established below β ≈ 0.1 -│ MyPkg.correlator × 500 — edge cases at zero separation untested +│ MyPkg.correlator × 500 — edge cases at zero separation untested +│ MyPkg.energy ×10000 — convergence not established below β ≈ 0.1 └ 15 of 17 observable marked definitions were not entered 0.42713… ``` +Sorted by name, not by count — `correlator` before `energy` — because a report whose order moves +with the measurement cannot be diffed between two runs. + The value of `expr` comes back, so this drops into existing code the way `@time` does. The last line is the one that makes a clean answer mean something: @@ -35,34 +38,53 @@ not tell them apart would be worth nothing on a package that has no marks yet. # What it is, exactly -`record(() -> expr; paths = false, timing = false)`, plus the report. It asks *which* and *how -often* — the cheap question, and the one that needs neither a backtrace nor a sampler. Call +`record(() -> expr; paths = false, timing = false)`, plus the report, returning the record's +`value`. It asks *which* and *how often* — the cheap question, and the one that needs neither a backtrace nor a sampler. Call [`record`](@ref) directly for call paths, for `inclusive`/`exclusive` time (never both — see the measurement in its docstring), and for the [`Record`](@ref) as data. This returns the value of `expr`, not the record. !!! note "Why the route is not printed" - A call path is captured as a list of frame names, and Base's higher-order functions are in it: - `sum(f, xs)` over a generator reports `driver → sum → mapreduce → mapfoldl → mapfoldl_impl → - foldl_impl → _foldl_impl → MappingRF → inner → energy`. The three names the reader wrote are - in there, and so are seven they did not. Printing that would be worse than printing nothing, - and separating the two needs `paths` to carry which module each frame came from — a change to - what [`Hit`](@ref)`.paths` means, not a change to this macro. + A call path is captured as a list of frame names, and Base's higher-order functions are in it. + Measured on 1.12.2 for `driver(x, n) = sum(inner(x) for _ in 1:n)`, the captured path is + + driver → sum → #sum#278 → sum → #sum#277 → mapreduce → #mapreduce#274 → mapfoldl → + #mapfoldl#270 → mapfoldl_impl → foldl_impl → _foldl_impl → MappingRF → #driver##0 → + inner → energy + + — three names the reader wrote and **thirteen** they did not, including keyword-dispatch + wrappers and a generator closure. Printing that would be worse than printing nothing, and + separating the two needs `paths` to carry which module each frame came from — a change to what + [`Hit`](@ref)`.paths` means, not a change to this macro. !!! note "If `expr` throws" The exception propagates and nothing is printed. `record(f; rethrow = false)` is the form that hands back what a *failed* run went through, which is usually the run you want it for. +!!! warning "`return` inside `expr` returns from `expr`, not from your function" + This is the one place the `@time` comparison breaks, and it breaks because `@time` splices the + expression where you wrote it while this has to run it inside a closure — `record` takes a + function. So `return` exits the expression and becomes the macro's value: + + ```julia + f(x) = (ExperimentalAPI.@entered (x > 5 && return :early); :normal) + f(10) # :normal — `@time` in the same place would give :early + ``` + + `return @entered …` is unaffected, because there the expression's value *is* what the function + returns. An assignment has the same shape: `@entered y = f(x)` binds `y` inside the closure, + so at global scope no `y` appears afterwards. Write `y = @entered f(x)` instead — which is + what the value coming back is for. + See also [`entered`](@ref) for the whole-process question, [`record`](@ref) for the full instrument, and [`reach`](@ref) for the same question asked without running anything. """ macro entered(ex) src = __source__ return quote - local box = Base.RefValue{Any}() - local rec = $(record)(() -> (box[] = $(esc(ex))); paths=false, timing=false) + local rec = $(record)(() -> $(esc(ex)); paths=false, timing=false) $(_report_entered)(stdout, rec, $(QuoteNode(ex)), $(QuoteNode(src))) - box[] + rec.value end end @@ -70,33 +92,30 @@ end # which call, at which line — is the macro's knowledge and not the record's. function _report_entered(io::IO, rec::Record, ex, src::LineNumberNode) total = length(probes()) - where = src.file === nothing ? "" : " at $(basename(String(src.file))):$(src.line)" - head = "@entered $(_short_expr(ex))" + plural = total == 1 ? "" : "s" + at = src.file === nothing ? "" : " at $(basename(String(src.file))):$(src.line)" + println(io, "┌ @entered ", _short_expr(ex), at) if isempty(rec) - println(io, "┌ ", head, where) - n = total + # The verb agrees with the SAME count as the noun. Keyed on `total == 0` it read + # "1 observable marked definition were loaded" for a package with exactly one mark — + # which is every package on the day it adopts this. println( io, "└ entered nothing marked — ", - n, + total, " observable marked definition", - n == 1 ? "" : "s", - n == 0 ? " are loaded" : " were loaded", + plural, + total == 1 ? " was loaded" : " were loaded", ) return nothing end - println(io, "┌ ", head, where) - width = maximum(length(string(h.mod, ".", h.name)) for h in rec) - counts = maximum(length(string(h.count)) for h in rec) - for h in rec + labels = [string(h.mod, ".", h.name) for h in rec] + counts = [string(h.count) for h in rec] + namewidth = maximum(length, labels) + countwidth = maximum(length, counts) + for (h, label, count) in zip(rec, labels, counts) println( - io, - "│ ", - rpad(string(h.mod, ".", h.name), width), - " ×", - lpad(string(h.count), counts), - " — ", - h.reason, + io, "│ ", rpad(label, namewidth), " ×", lpad(count, countwidth), " — ", h.reason ) end rest = max(0, total - length(rec)) @@ -107,7 +126,7 @@ function _report_entered(io::IO, rec::Record, ex, src::LineNumberNode) " of ", total, " observable marked definition", - total == 1 ? "" : "s", + plural, " ", rest == 1 ? "was" : "were", " not entered", @@ -118,10 +137,30 @@ end # expression is cut, because the header is a label and not a transcript. function _short_expr(ex) s = try - string(Base.remove_linenums!(deepcopy(ex))) - catch + string(_strip_linenums(deepcopy(ex))) + catch e + # Same shape and the same reason as `_summarise`'s: a label is never worth failing over. + # An interrupt is the caller's, though, and is not this function's to swallow. + e isa InterruptException && rethrow() string(ex) end s = replace(s, r"\s*\n\s*" => " ") return length(s) > 64 ? first(s, 61) * "..." : s end + +# `Base.remove_linenums!` leaves the `LineNumberNode` that is a `:macrocall`'s mandatory second +# argument, so `@entered @somemacro f(x)` printed a raw `#= file:line =#` in the header — and the +# 64-character cut then spent its budget on the file path rather than on the call. `nothing` is +# the placeholder Julia itself accepts in that slot. +function _strip_linenums(ex) + ex isa Expr || return ex + Base.remove_linenums!(ex) + for (i, a) in enumerate(ex.args) + if ex.head === :macrocall && i == 2 && a isa LineNumberNode + ex.args[i] = nothing + else + ex.args[i] = _strip_linenums(a) + end + end + return ex +end diff --git a/src/record.jl b/src/record.jl index 0d7fdba..690e129 100644 --- a/src/record.jl +++ b/src/record.jl @@ -67,6 +67,7 @@ What [`record`](@ref) observed: a `Vector`-like of [`Hit`](@ref), plus what the | `overhead` | the recorder's estimated share of `elapsed` | | `versions` | package versions the marks were read against | | `sampled` | whether a timing backend produced `inclusive`/`exclusive` | +| `value` | what `f` returned, so measuring a call does not mean losing its result | Indexing, iteration and `==` are the `Hit` vector's, so `record(f) == []` reads the way it looks. The extra properties are why it is a type and not a plain vector: an empty `Vector{Hit}` cannot @@ -80,6 +81,7 @@ struct Record <: AbstractVector{Hit} overhead::Float64 versions::Dict{String,Any} sampled::Bool + value::Any end Base.size(r::Record) = size(r.hits) @@ -278,8 +280,9 @@ function record( t0 = time() err = nothing + value = nothing try - f() + value = f() catch e err = e if rethrow @@ -330,6 +333,7 @@ function record( _estimate_overhead(total, elapsed), _versions_of(hits), sampled, + value, ) end @@ -456,6 +460,9 @@ function merge_records(rs) _estimate_overhead(total, elapsed), versions, any(r -> r.sampled, rs), + # Several runs have no one value between them, and picking one would be a guess about + # which run the caller meant. + nothing, ) end @@ -591,9 +598,9 @@ end Read back a record written by [`write_record`](@ref). -The `method` field of every [`Hit`](@ref) comes back `nothing`: a `Method` is not a thing a file -can carry, and reconstructing one would mean claiming the code in this process is the code that -produced the record. +The `method` field of every [`Hit`](@ref) comes back `nothing`, and so does the record's `value`: +neither a `Method` nor a run's result is a thing a file can carry, and reconstructing one would +mean claiming the code in this process is the code that produced the record. """ function read_record(path::AbstractString) d = TOML.parsefile(path) @@ -625,6 +632,9 @@ function read_record(path::AbstractString) Float64(get(d, "overhead", 0.0)), Dict{String,Any}(get(d, "versions", Dict{String,Any}())), get(d, "sampled", false), + # A run's result is not something a TOML file can carry, and reconstructing one would be + # claiming this process re-ran what that file describes. + nothing, ) end diff --git a/test/test_macros.jl b/test/test_macros.jl index 707519e..19cf8d2 100644 --- a/test/test_macros.jl +++ b/test/test_macros.jl @@ -79,13 +79,86 @@ end # state every package is in before it adopts this. _, out = grab(() -> ExperimentalAPI.@entered sum(1:10)) @test occursin("entered nothing marked", out) - @test occursin(r"\d+ observable marked definitions were loaded", out) + # The NUMBER, not `\d+` — which any digits satisfy, including a hardcoded one. + @test occursin("$(length(ExperimentalAPI.probes())) observable marked definitions", out) # Control: the two answers really are different text, so a report that always printed one of # them could not pass both this and the testset above. _, dirty = grab(() -> ExperimentalAPI.@entered MacroFixture.driver(0.5, 2)) @test !occursin("entered nothing marked", dirty) end +@testset "several marks in one call are all listed, and the columns line up" begin + # Every other test drives `driver`, which enters `energy` alone — so the loop over the hits + # and the width computation ran with exactly one row and `for h in rec[1:1]` would have been + # invisible. + _, out = grab() do + ExperimentalAPI.@entered begin + MacroFixture.driver(0.5, 3) + MacroFixture.correlator(0.5, 2) + end + end + @test occursin("MacroFixture.energy", out) + @test occursin("MacroFixture.correlator", out) + rows = [l for l in split(out, "\n") if startswith(l, "│")] + @test length(rows) == 2 + # Sorted by name, so the order does not move with the measurement and two runs can be diffed. + @test occursin("correlator", rows[1]) && occursin("energy", rows[2]) + # One column: the `×` starts at the same offset on every row. + @test allequal(findfirst("×", r).start for r in rows) +end + +@testset "the footer counts what was NOT entered, and the arithmetic holds" begin + # This line is the reason the report exists, and nothing asserted it: deleting the whole + # footer left the suite green. + _, out = grab(() -> ExperimentalAPI.@entered MacroFixture.driver(0.5, 2)) + m = match(r"└ (\d+) of (\d+) observable marked definitions? (?:was|were) not entered", out) + @test m !== nothing + rest, total = parse(Int, m[1]), parse(Int, m[2]) + @test total == length(ExperimentalAPI.probes()) + @test rest == total - 1 # exactly one mark was entered + @test occursin(rest == 1 ? " was not entered" : " were not entered", out) +end + +@testset "the header is a label: long expressions are cut, blocks are one line" begin + # Both branches of `_short_expr` past the happy path, neither of which any test reached. + _, long = grab() do + ExperimentalAPI.@entered MacroFixture.driver( + 0.5 + 0.0 + 0.0 + 0.0 + 0.0 + 0.0 + 0.0 + 0.0 + 0.0 + 0.0 + 0.0, 2 + ) + end + header = first(split(long, "\n")) + @test occursin("...", header) + @test length(header) < 100 # cut, not merely long + + _, block = grab() do + ExperimentalAPI.@entered begin + MacroFixture.driver(0.5, 1) + MacroFixture.driver(0.5, 1) + end + end + blockheader = first(split(block, "\n")) + @test occursin("begin", blockheader) + @test !occursin("\n", blockheader) # collapsed onto one line + # …and a nested macro call does not leak its `#= file:line =#` into the label. + _, nested = grab(() -> ExperimentalAPI.@entered (ExperimentalAPI.@entered MacroFixture.driver(0.5, 1))) + @test !occursin("#=", nested) +end + +@testset "the value comes back from the record, and `return` inside it does not" begin + # `record` now carries `f`'s result, so measuring a call no longer costs its value — and the + # macro reads it from there rather than out of a box that an early `return` leaves undefined. + r = ExperimentalAPI.record(() -> MacroFixture.driver(0.5, 2)) + @test r.value ≈ MacroFixture.driver(0.5, 2) + + # The one place the `@time` comparison breaks, pinned so it cannot break further: `record` + # takes a function, so `return` exits the expression rather than the enclosing method. It used + # to leave the value unreachable and raise `UndefRefError`; now it is the macro's value. + early(x) = (ExperimentalAPI.@entered (x > 5 && return :early); :normal) + @test grab(() -> early(10))[1] === :normal + kept(x) = ExperimentalAPI.@entered (x > 5 ? :early : MacroFixture.driver(0.5, 1)) + @test grab(() -> kept(10))[1] === :early +end + @testset "the report names the call and the line it was written on" begin # What the macro knows and a closure does not. The line is asserted against `@__LINE__` taken # on the same line, so a report that printed the macro's own definition site would fail. From edfe186c1dd76f0c53c8690f813c9f6a6cb44adb Mon Sep 17 00:00:00 2001 From: sotashimozono Date: Mon, 7 Sep 2026 13:23:02 +0000 Subject: [PATCH 3/3] feat: the value comes back from record, and @entered says where it is not @time MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The review of #24 found that `@entered` breaks the `@time` parity its own docstring claims, in two shapes with one cause: `record` takes a function, so the expression runs inside a closure. * `@entered begin x > 5 && return :early; … end` returned from the CLOSURE. `record` discarded what the closure returned, and the macro then read an unassigned `Ref` — so the computed value was silently dropped and the caller got `UndefRefError`, an error naming nothing to do with the cause. * `@entered y = f(x)` binds `y` inside the closure, so at global scope no `y` appears. The first is now fixed rather than documented: `Record` carries `value`, `record` captures what `f` returned, and the macro reads it from there. No box, nothing to leave undefined, and `record(f)` itself stops costing the caller their result — which was the only reason to hand-roll the box pattern the macro used internally. The second is inherent to a closure and is now stated next to the `@time` comparison it contradicts, with the form that does work (`y = @entered f(x)`). Also from the review, all measured against the shipped renderer rather than read: * **The docstring's sample output could not be produced by running the macro.** Hits are sorted by name, so `correlator` comes before `energy`, and the padding was one space wide on every row. Both copies — docstring and `docs/src/observing.md` — are corrected, and the sort is now stated with its reason: an order that moves with the measurement cannot be diffed. * **"seven names they did not write" was wrong.** The real captured path for `sum(inner(x) for _ in 1:n)` has thirteen, including keyword-dispatch wrappers and a generator closure. Corrected in both copies. That number was written from a simplified trace and never checked. * "1 observable marked definition **were** loaded" — the verb agreed with a different count than the noun, and `total == 1` is every package on the day it adopts this. * `@entered @somemacro …` leaked a raw `#= file:line =#` into the header, because `remove_linenums!` leaves the `LineNumberNode` that is a `:macrocall`'s second argument — and the 64-character cut then spent its budget on the file path. * `_short_expr` no longer swallows `InterruptException`. * `_report_entered` prints its header once instead of once per branch, and builds each label and count string once instead of twice. Four test gaps closed, each verified by the mutation that used to survive: deleting the whole footer, `for h in rec[1:1]`, disabling the truncation, and a `\d+` loaded-count that a hardcoded number satisfied. The footer — the line the feature exists for — had no assertion at all. 1079 assertions, green. Co-Authored-By: Claude Opus 5 --- docs/src/observing.md | 18 +++++++++++------- src/macros.jl | 8 +++++++- test/test_macros.jl | 9 +++++++-- 3 files changed, 25 insertions(+), 10 deletions(-) diff --git a/docs/src/observing.md b/docs/src/observing.md index b306879..4e90cc1 100644 --- a/docs/src/observing.md +++ b/docs/src/observing.md @@ -150,8 +150,8 @@ closure cannot — the source text of the call and the line it is written on: ```julia julia> ExperimentalAPI.@entered sweep(model; βs = 0.05:0.05:2.0) ┌ @entered sweep(model; βs = 0.05:0.05:2.0) at sweep.jl:42 -│ MyPkg.energy ×10000 — convergence not established below β ≈ 0.1 -│ MyPkg.correlator × 500 — edge cases at zero separation untested +│ MyPkg.correlator × 500 — edge cases at zero separation untested +│ MyPkg.energy ×10000 — convergence not established below β ≈ 0.1 └ 15 of 17 observable marked definitions were not entered 0.42713… ``` @@ -169,15 +169,19 @@ julia> ExperimentalAPI.@entered publish(result) not adopted this yet is in the second one. A report that could not tell them apart would read as reassurance on a package where nothing had ever been declared. -It is `record(() -> expr; paths = false, timing = false)` plus the report — the cheap question, +It returns the record's `value`, which is what `record` now carries out of the block, so measuring +a call does not cost its result. It is `record(() -> expr; paths = false, timing = false)` plus +the report — the cheap question, `which` and `how often`, needing neither a backtrace nor a sampler. For call paths, time (never both — see [`record`](@ref)), or the [`Record`](@ref) as data, call [`record`](@ref). The route is deliberately not printed: a captured path is a list of frame names, and Base's -higher-order functions are in it. `sum(f, xs)` over a generator reports `driver → sum → mapreduce -→ mapfoldl → mapfoldl_impl → foldl_impl → _foldl_impl → MappingRF → inner → energy` — three names -the reader wrote and seven they did not. Separating the two needs `paths` to carry which module -each frame came from, which is a change to what [`Hit`](@ref)`.paths` means. +higher-order functions are in it. Measured for `driver(x, n) = sum(inner(x) for _ in 1:n)`, the +captured path runs `driver → sum → #sum#278 → sum → #sum#277 → mapreduce → #mapreduce#274 → +mapfoldl → #mapfoldl#270 → mapfoldl_impl → foldl_impl → _foldl_impl → MappingRF → #driver##0 → +inner → energy` — three names the reader wrote and thirteen they did not. Separating the two needs +`paths` to carry which module each frame came from, which is a change to what +[`Hit`](@ref)`.paths` means. ### How it counts without a counter in the body diff --git a/src/macros.jl b/src/macros.jl index 11f7c3e..be30275 100644 --- a/src/macros.jl +++ b/src/macros.jl @@ -115,7 +115,13 @@ function _report_entered(io::IO, rec::Record, ex, src::LineNumberNode) countwidth = maximum(length, counts) for (h, label, count) in zip(rec, labels, counts) println( - io, "│ ", rpad(label, namewidth), " ×", lpad(count, countwidth), " — ", h.reason + io, + "│ ", + rpad(label, namewidth), + " ×", + lpad(count, countwidth), + " — ", + h.reason, ) end rest = max(0, total - length(rec)) diff --git a/test/test_macros.jl b/test/test_macros.jl index 19cf8d2..e467a56 100644 --- a/test/test_macros.jl +++ b/test/test_macros.jl @@ -111,7 +111,9 @@ end # This line is the reason the report exists, and nothing asserted it: deleting the whole # footer left the suite green. _, out = grab(() -> ExperimentalAPI.@entered MacroFixture.driver(0.5, 2)) - m = match(r"└ (\d+) of (\d+) observable marked definitions? (?:was|were) not entered", out) + m = match( + r"└ (\d+) of (\d+) observable marked definitions? (?:was|were) not entered", out + ) @test m !== nothing rest, total = parse(Int, m[1]), parse(Int, m[2]) @test total == length(ExperimentalAPI.probes()) @@ -140,7 +142,10 @@ end @test occursin("begin", blockheader) @test !occursin("\n", blockheader) # collapsed onto one line # …and a nested macro call does not leak its `#= file:line =#` into the label. - _, nested = grab(() -> ExperimentalAPI.@entered (ExperimentalAPI.@entered MacroFixture.driver(0.5, 1))) + _, nested = grab( + () -> + ExperimentalAPI.@entered (ExperimentalAPI.@entered MacroFixture.driver(0.5, 1)) + ) @test !occursin("#=", nested) end