diff --git a/docs/src/api-runtime.md b/docs/src/api-runtime.md index b27693e..1ff17f4 100644 --- a/docs/src/api-runtime.md +++ b/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"] ``` diff --git a/docs/src/observing.md b/docs/src/observing.md index 589bfd9..b306879 100644 --- a/docs/src/observing.md +++ b/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 diff --git a/src/ExperimentalAPI.jl b/src/ExperimentalAPI.jl index 8dfc394..13f4119 100644 --- a/src/ExperimentalAPI.jl +++ b/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 diff --git a/src/macros.jl b/src/macros.jl new file mode 100644 index 0000000..b2a1434 --- /dev/null +++ b/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 diff --git a/test/runtests.jl b/test/runtests.jl index b04644d..bee91a3 100644 --- a/test/runtests.jl +++ b/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; diff --git a/test/test_macros.jl b/test/test_macros.jl new file mode 100644 index 0000000..707519e --- /dev/null +++ b/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