feat: @entered — ask which marked definitions one call went through

docs/src/api-runtime.md

@@ -8,5 +8,5 @@ What a run went through ([Observing](@ref)), and what a caller could reach ([Ana
 
 ```@autodocs
 Modules = [ExperimentalAPI]
-Pages = ["detect.jl", "record.jl", "reach.jl"]
+Pages = ["detect.jl", "record.jl", "macros.jl", "reach.jl"]
 ```

docs/src/observing.md

@@ -141,6 +141,44 @@ the way they look — with the properties an empty vector could not carry:
 | `overhead` | the recorder's estimated share of the elapsed time, from a calibrated per-hit cost |
 | `versions` | `energy` being experimental in v0.3 says nothing about v0.9 |
 
+### Asking about one call
+
+`record(() -> f(x))` is the function form, and it is what everything here is built on.
+[`@entered`](@ref) is the same question asked about an expression, and it knows two things a
+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
+└ 15 of 17 observable marked definitions were not entered
+0.42713…
+```
+
+It returns the value of the expression, so it drops into existing code the way `@time` does. The
+last line is what makes a clean answer mean anything:
+
+```julia
+julia> ExperimentalAPI.@entered publish(result)
+┌ @entered publish(result)   at sweep.jl:57
+└ entered nothing marked — 17 observable marked definitions were loaded
+```
+
+"Entered nothing" and "nothing is marked anywhere" are different states, and a package that has
+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,
+`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.
+
 ### How it counts without a counter in the body
 
 The emitted statement never changes. Opening a block clears every probe's flag, so the

src/ExperimentalAPI.jl

@@ -81,7 +81,7 @@ public Probe, Entry, entered, marked_modules, probes, detecting, summary_text
 public overhead_when_detecting
 public Hit, Record, Attribution, TimingBackend, timing_backend
 public record, recording, merge_records, attribute, experimental_fraction
-public write_record, read_record, assert_clean
+public write_record, read_record, assert_clean, @entered
 
 # Analysing — what code could reach
 public Reach,
@@ -114,6 +114,7 @@ include("query.jl")      # reading a module's marks back out, by name and by met
 include("audit.jl")      # the public surface, and the names and methods neither account covers
 include("reach.jl")      # what a caller depends on without naming it
 include("record.jl")     # the opt-in layer: counts, call paths, and how much of the run
+include("macros.jl")     # the expression-level spelling of the observing layer
 include("verify.jl")     # how well the tests exercise what is marked
 include("lifecycle.jl")  # the mark's exit
 include("docsnote.jl")   # the mark, in the rendered documentation

src/macros.jl

@@ -0,0 +1,127 @@
+# The expression-level spelling of the observing layer.
+#
+# `record(() -> f(x))` is the function form and it is what everything here is built on. The macro
+# earns its place by knowing two things a closure cannot: the source text of the expression, and
+# the line it was written on. A report that says which call went through unvalidated code, and
+# where that call is, is a different thing from a list of names.
+
+"""
+    @entered expr
+
+Evaluate `expr`, print which marked definitions it went through, and return its value.
+
+The question [`entered`](@ref) answers about a whole process, asked about one call:
+
+```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
+└ 15 of 17 observable marked definitions were not entered
+0.42713…
+```
+
+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:
+
+```julia
+julia> ExperimentalAPI.@entered publish(result)
+┌ @entered publish(result)   at sweep.jl:57
+└ entered nothing marked — 17 observable marked definitions were loaded
+```
+
+"Entered nothing" and "nothing is marked anywhere" are different states, and a report that could
+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`](@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.
+
+!!! 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.
+
+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)
+        $(_report_entered)(stdout, rec, $(QuoteNode(ex)), $(QuoteNode(src)))
+        box[]
+    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))"
+    if isempty(rec)
+        println(io, "┌ ", head, where)
+        n = total
+        println(
+            io,
+            "└ entered nothing marked — ",
+            n,
+            " observable marked definition",
+            n == 1 ? "" : "s",
+            n == 0 ? " are 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
+        println(
+            io,
+            "│   ",
+            rpad(string(h.mod, ".", h.name), width),
+            "  ×",
+            lpad(string(h.count), counts),
+            " — ",
+            h.reason,
+        )
+    end
+    rest = max(0, total - length(rec))
+    return println(
+        io,
+        "└ ",
+        rest,
+        " of ",
+        total,
+        " observable marked definition",
+        total == 1 ? "" : "s",
+        " ",
+        rest == 1 ? "was" : "were",
+        " not entered",
+    )
+end
+
+# The expression as the author wrote it, near enough. Line numbers are stripped and a long
+# 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(ex)
+    end
+    s = replace(s, r"\s*\n\s*" => " ")
+    return length(s) > 64 ? first(s, 61) * "..." : s
+end

test/runtests.jl

@@ -9,6 +9,7 @@ using Test
     include("test_audit.jl")
     include("test_release.jl")
     include("test_ext.jl")
+    include("test_macros.jl")
     include("test_precompile.jl")
     include("test_dogfood.jl")
     # The case matrix. Written before the implementation, so most of it is @test_broken;

test/test_macros.jl

@@ -0,0 +1,120 @@
+# `@entered expr` — the expression-level spelling of the observing layer.
+#
+# Scope: what the macro adds over `record(() -> expr)`. Two of those are things only a macro can
+# get wrong — evaluating its argument twice, and reporting a location that is not the caller's —
+# and one is the distinction the whole report exists for: a call that entered nothing is not the
+# same state as a package that has nothing marked.
+
+using ExperimentalAPI: ExperimentalAPI, @experimental
+using Test
+
+module MacroFixture
+
+using ExperimentalAPI
+
+public energy, correlator, driver, cold, boom
+
+@experimental "convergence not established below β ≈ 0.1" energy(x) = x * 1.0000001
+@experimental "edge cases at zero separation untested" correlator(x, r) = x / (r + 1)
+@experimental "never exercised by this file" cold(x) = x
+
+"Settled."
+partition(x) = exp(-x)
+inner(x) = energy(x) + partition(x)
+driver(x, n) = sum(inner(x) for _ in 1:n)
+
+"Documented, and it throws."
+boom(x) = (energy(x); error("boom"))
+
+# Counts how many times the macro evaluated its argument. A macro that splices `expr` twice —
+# once to run and once to report — doubles every count it prints, and the count is the answer.
+const CALLS = Ref(0)
+bump(x) = (CALLS[] += 1; driver(x, 3))
+
+end # module MacroFixture
+
+"Everything `f` wrote to `stdout`, and its value."
+function grab(f)
+    old = stdout
+    rd, wr = redirect_stdout()
+    value = try
+        f()
+    finally
+        redirect_stdout(old)
+        close(wr)
+    end
+    return value, read(rd, String)
+end
+
+@testset "@entered returns the value of the expression, not the record" begin
+    # The property that lets it be dropped into existing code, the way `@time` is.
+    v, _ = grab(() -> ExperimentalAPI.@entered MacroFixture.driver(0.5, 4))
+    @test v isa Float64
+    @test v ≈ MacroFixture.driver(0.5, 4)
+    # Control: it is emphatically NOT the record, which is what a first implementation returns.
+    @test !(v isa AbstractVector)
+end
+
+@testset "the expression is evaluated exactly once" begin
+    # A macro that splices `expr` into both the run and the report doubles every count it prints,
+    # and the count is the answer. Nothing else in this file would notice.
+    MacroFixture.CALLS[] = 0
+    grab(() -> ExperimentalAPI.@entered MacroFixture.bump(0.5))
+    @test MacroFixture.CALLS[] == 1
+end
+
+@testset "the report names what was entered, how often, and why" begin
+    _, out = grab(() -> ExperimentalAPI.@entered MacroFixture.driver(0.5, 10))
+    @test occursin("MacroFixture.energy", out)
+    @test occursin("×10", out)                                   # the count, not just presence
+    @test occursin("convergence not established", out)           # the reason travels
+    # A definition that was never entered is ABSENT, not reported with a count of zero.
+    @test !occursin("cold", out)
+    @test !occursin("×0", out)
+end
+
+@testset "a call that entered nothing says so, and says what was loaded" begin
+    # The distinction the last line exists for. Without the count, "entered nothing marked" reads
+    # the same on a package with seventeen marks and on one with none — and the second is the
+    # 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)
+    # 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 "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.
+    line = 0
+    _, out = grab() do
+        line = @__LINE__
+        ExperimentalAPI.@entered MacroFixture.driver(0.5, 2)
+    end
+    @test occursin("driver(0.5, 2)", out)
+    @test occursin("test_macros.jl:$(line + 1)", out)
+end
+
+@testset "recording is not left on" begin
+    grab(() -> ExperimentalAPI.@entered MacroFixture.driver(0.5, 2))
+    @test ExperimentalAPI.recording() === false
+end
+
+@testset "an exception propagates, and the flag it set survives" begin
+    # Stated rather than silent: the report is not printed for a run that threw. `record` with
+    # `rethrow = false` is the form that reports what a failed run went through, and the
+    # docstring says so.
+    @test_throws ErrorException grab(() -> ExperimentalAPI.@entered MacroFixture.boom(0.5))
+    # …and the default layer still saw it, because that is the layer that costs nothing.
+    @test :energy in [e.name for e in ExperimentalAPI.entered(MacroFixture)]
+end
+
+@testset "@experimental is still the only exported name" begin
+    # `@entered` is `public` and qualified, like everything but the mark itself. Written at a
+    # call site rather than a definition site, it is the one that would most tempt an export.
+    @test Base.ispublic(ExperimentalAPI, Symbol("@entered"))
+    @test !Base.isexported(ExperimentalAPI, Symbol("@entered"))
+end