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
26 changes: 22 additions & 4 deletions src/record.jl
Original file line number Diff line number Diff line change
Expand Up @@ -160,7 +160,7 @@ const _DEPTH = Ref(0)
const _RECORD_LOCK = ReentrantLock()

"""
record(f; paths = true, timing = true, with_profile = false, rethrow = true, maxdepth) -> Record
record(f; paths = true, timing = false, with_profile = false, rethrow = true) -> Record

Run `f` and report which marked definitions it entered, how often, and by which paths.

Expand All @@ -176,8 +176,8 @@ says what happened, and enumerating what did not is [`experimental`](@ref)'s job

| keyword | |
|---|---|
| `paths` | capture call paths. Bounded — see [`Hit`](@ref) — but still the expensive part |
| `timing` | ask the [`TimingBackend`](@ref) for `inclusive`/`exclusive`. Ignored if none is loaded |
| `paths` | capture call paths. Bounded — see [`Hit`](@ref) — and **on by default** |
| `timing` | ask the [`TimingBackend`](@ref) for `inclusive`/`exclusive`. Off by default, and **cannot be combined with `paths`** |
| `with_profile` | leave whatever is already in the profile buffer alone instead of clearing it |
| `rethrow` | `false` returns the record for the part of `f` that ran instead of propagating |

Expand All @@ -190,10 +190,28 @@ count.
Every marked body takes its write path while a recording is open. The record reports the
recorder's estimated share of the elapsed time in `overhead`; [`overhead_when_detecting`](@ref)
is the other number, and it is 3%.

!!! warning "Paths and time are two instruments, and they cannot be read at once"
Capturing a call path calls `backtrace()`; the timing backend's sampler walks the same
threads' stacks from outside, and two unwinders on one stack is a segmentation fault rather
than a wrong number. Measured on 1.12.7 with 150 threaded records per run, four runs of each
combination: paths alone **0/4** crashed, timing alone **0/4**, both **2/4**. Asking for both
is refused rather than risked, and the default is `paths` — the instrument that needs no
sampler and has no global side effect.
"""
function record(
f; paths::Bool=true, timing::Bool=true, with_profile::Bool=false, rethrow::Bool=true
f; paths::Bool=true, timing::Bool=false, with_profile::Bool=false, rethrow::Bool=true
)
(paths && timing) && throw(
ArgumentError(
"record: `paths` and `timing` cannot both be collected in one block. Capturing a " *
"call path calls `backtrace()`, and the timing backend's sampler walks the same " *
"threads' stacks from outside — measured on 1.12.7, four runs of each combination: " *
"paths alone 0/4 crashed, timing alone 0/4, both 2/4 with a segmentation fault and " *
"no Julia backtrace. Ask for one: `record(f)` for counts and paths, " *
"`record(f; paths = false, timing = true)` for counts and time.",
),
)
ps = probes()
slots = Threads.maxthreadid()
sampled = false
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` | 15 | 15 | 0 | the mark's EXIT, and an entry point that is a module rather than a function |
| `test_spec_profile.jl` | 42 | 42 | 0 | what a real run went through, how often, and how much of it |
| `test_spec_profile.jl` | 43 | 43 | 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** | **178** | **178** | **0** | |
| **10 files** | **179** | **179** | **0** | |
<!-- END GENERATED -->

The table is generated and pinned by `test/test_spec_table.jl`, which fails if it goes stale —
Expand Down
43 changes: 39 additions & 4 deletions test/spec/test_spec_profile.jl
Original file line number Diff line number Diff line change
Expand Up @@ -200,15 +200,18 @@ end
# Long enough to be sampled: the timing backend is Julia's sampling profiler, and a run that
# finishes inside one sampling interval has no fraction to report. Two million iterations of
# a recorded body is tens of milliseconds — hundreds of samples, not a handful.
r = ExperimentalAPI.record(() -> Sim.driver(M, 2_000_000))
# `paths = false` because the two instruments cannot be read at once: `backtrace()` and the
# sampler both unwind the same threads' stacks, and asking for both is refused — see the
# measurement in `record`'s docstring, and the testset that pins the refusal below.
r = ExperimentalAPI.record(() -> Sim.driver(M, 2_000_000); paths=false, timing=true)
@test r.sampled # …the backend really was loaded
f = ExperimentalAPI.experimental_fraction(r)
@test 0.0 < f <= 1.0
end

@testset "inclusive and exclusive time are distinguished" begin
# Scope: a marked wrapper over settled code is not a marked kernel.
h = first(ExperimentalAPI.record(() -> Sim.driver(M, 1000)))
h = first(ExperimentalAPI.record(() -> Sim.driver(M, 1000); paths=false, timing=true))
@test h.inclusive >= h.exclusive
@test h.inclusive isa Float64
end
Expand Down Expand Up @@ -311,6 +314,36 @@ end
@test ExperimentalAPI.record(() -> Sim.driver(M, 100))[1].count == 100
end

@testset "paths and time cannot be collected in one block" begin
# A conjunction, and each half was measured alone before the pair was refused. `backtrace()`
# unwinds the calling thread; the sampler unwinds the same threads from outside. 1.12.7, 150
# threaded records per run, four runs of each combination:
#
# paths alone 0/4 crashed
# timing alone 0/4
# both 2/4 segmentation fault, no Julia backtrace
#
# So the pair is refused rather than risked, and the refusal names the measurement rather
# than saying "unsupported".
e = try
ExperimentalAPI.record(() -> Sim.driver(M, 1); paths=true, timing=true)
nothing
catch err
err
end
@test e isa ArgumentError
msg = sprint(showerror, e)
@test occursin("backtrace", msg)
@test occursin("2/4", msg) # the measurement, not just a prohibition
# Controls: each alone is accepted, which is what makes the refusal about the PAIR.
@test ExperimentalAPI.record(() -> Sim.driver(M, 1); paths=true, timing=false) isa
AbstractVector
@test ExperimentalAPI.record(() -> Sim.driver(M, 1); paths=false, timing=true) isa
AbstractVector
# …and the default is the one with no sampler, so an ordinary `record` never asks for both.
@test ExperimentalAPI.record(() -> Sim.driver(M, 1)).sampled === false
end

@testset "detection is on by default; counting is not" begin
@test ExperimentalAPI.detecting() === true
@test ExperimentalAPI.recording() === false
Expand Down Expand Up @@ -464,11 +497,13 @@ end # module Hot
Profile.@profile Hot.grind(2_000_000)
before = Profile.len_data()
@test before > 0
r = ExperimentalAPI.record(() -> Sim.driver(M, 10); with_profile=true)
r = ExperimentalAPI.record(
() -> Sim.driver(M, 10); paths=false, timing=true, with_profile=true
)
@test r isa AbstractVector
@test Profile.len_data() >= before
# Control: without the keyword the buffer is cleared, so the keyword is doing the work.
ExperimentalAPI.record(() -> Sim.driver(M, 10))
ExperimentalAPI.record(() -> Sim.driver(M, 10); paths=false, timing=true)
@test Profile.len_data() < before
Profile.clear()
end
Expand Down
Loading