diff --git a/src/record.jl b/src/record.jl index 9859a28..f59c516 100644 --- a/src/record.jl +++ b/src/record.jl @@ -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. @@ -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 | @@ -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 diff --git a/test/spec/README.md b/test/spec/README.md index c517726..4bbbe17 100644 --- a/test/spec/README.md +++ b/test/spec/README.md @@ -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** | | The table is generated and pinned by `test/test_spec_table.jl`, which fails if it goes stale — diff --git a/test/spec/test_spec_profile.jl b/test/spec/test_spec_profile.jl index 114864f..8c99583 100644 --- a/test/spec/test_spec_profile.jl +++ b/test/spec/test_spec_profile.jl @@ -200,7 +200,10 @@ 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 @@ -208,7 +211,7 @@ 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 @@ -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 @@ -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