Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
75 changes: 54 additions & 21 deletions src/record.jl
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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)
Expand Down
4 changes: 2 additions & 2 deletions test/spec/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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** | |
<!-- END GENERATED -->

The table is generated and pinned by `test/test_spec_table.jl`, which fails if it goes stale —
Expand Down
62 changes: 62 additions & 0 deletions test/spec/test_spec_profile.jl
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
Loading