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 b2a1434..be30275 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,31 +92,34 @@ 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), + 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 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..e467a56 100644 --- a/test/test_macros.jl +++ b/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.