feat: the value comes back from record, and @entered says where it is not @time

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
 

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,66 +38,88 @@ 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
 
 # The report. Written here rather than as a `show` method on `Record`, because what it says —
 # 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),
+            rpad(label, namewidth),
             "  ×",
-            lpad(string(h.count), counts),
+            lpad(count, countwidth),
             " — ",
             h.reason,
         )
@@ -107,7 +132,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 +143,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

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
 

test/test_macros.jl

@@ -79,13 +79,91 @@ 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.