Make TimespanLogging cheap enough to leave on

.buildkite/pipeline-julia.yml

@@ -127,6 +127,7 @@ steps:
       arch: aarch64
     env:
       CI_USE_OPENCL: "1"
+    command: "julia --project -e 'using Pkg; Pkg.develop(;path=\"lib/TimespanLogging\")'"
 
   # MPI × OpenCL SPMD datadeps suite. Runs on the same macOS/aarch64 agent as the
   # non-MPI OpenCL job, but drives test/mpi_opencl.jl under MPI.jl's bundled
@@ -142,7 +143,7 @@ steps:
       os: macos
       arch: aarch64
     command: |
-      julia --project=test/openclenv -e 'using Pkg; Pkg.develop(PackageSpec(path=pwd())); Pkg.instantiate()'
+      julia --project=test/openclenv -e 'using Pkg; Pkg.develop([PackageSpec(path=pwd()), PackageSpec(path="lib/TimespanLogging")]); Pkg.instantiate()'
       julia --project=test/openclenv test/run_mpi.jl 2 2 test/mpi_opencl.jl
 
   - label: Julia 1 - TimespanLogging
@@ -153,7 +154,7 @@ steps:
           version: "1"
       - JuliaCI/julia-coverage#v1:
           codecov: true
-    command: "julia --project -e 'using Pkg; Pkg.instantiate(); Pkg.develop(;path=\"lib/TimespanLogging\"); Pkg.test(\"TimespanLogging\")'"
+    command: "julia --project -e 'using Pkg; Pkg.develop(;path=\"lib/TimespanLogging\"); Pkg.instantiate(); Pkg.test(\"TimespanLogging\")'"
 
   - label: Julia 1 - DaggerWebDash
     <<: *test
@@ -163,7 +164,7 @@ steps:
           version: "1"
       - JuliaCI/julia-coverage#v1:
           codecov: true
-    command: "julia -e 'using Pkg; Pkg.develop(;path=pwd()); Pkg.develop(;path=\"lib/TimespanLogging\"); Pkg.develop(;path=\"lib/DaggerWebDash\"); include(\"lib/DaggerWebDash/test/runtests.jl\")'"
+    command: "julia -e 'using Pkg; Pkg.develop([PackageSpec(path=pwd()), PackageSpec(path=\"lib/TimespanLogging\"), PackageSpec(path=\"lib/DaggerWebDash\")]); include(\"lib/DaggerWebDash/test/runtests.jl\")'"
 
   - label: "Benchmarks (vs master)"
     timeout_in_minutes: 120

.buildkite/pipeline.yml

@@ -1,6 +1,7 @@
 .gputest: &gputest
   timeout_in_minutes: 60
   if: build.message !~ /\[skip tests\]/
+  command: "julia --project -e 'using Pkg; Pkg.develop(;path=\"lib/TimespanLogging\")'"
 
 # MPI × GPU jobs launch the SPMD datadeps suite (test/mpi_<backend>.jl) under
 # `mpiexec`. They use only the `julia` plugin (not `julia-test`, which would run
@@ -74,7 +75,7 @@ steps:
     agents:
       queue: "cuda"
     command: |
-      julia --project=test/cudaenv -e 'using Pkg; Pkg.develop(PackageSpec(path=pwd())); Pkg.instantiate()'
+      julia --project=test/cudaenv -e 'using Pkg; Pkg.develop([PackageSpec(path=pwd()), PackageSpec(path="lib/TimespanLogging")]); Pkg.instantiate()'
       julia --project=test/cudaenv test/run_mpi.jl 2 2 test/mpi_cuda.jl
 
   - label: Julia 1.11 (ROCm, MPI)
@@ -85,7 +86,7 @@ steps:
     agents:
       queue: "rocm"
     command: |
-      julia --project=test/rocmenv -e 'using Pkg; Pkg.develop(PackageSpec(path=pwd())); Pkg.instantiate()'
+      julia --project=test/rocmenv -e 'using Pkg; Pkg.develop([PackageSpec(path=pwd()), PackageSpec(path="lib/TimespanLogging")]); Pkg.instantiate()'
       julia --project=test/rocmenv test/run_mpi.jl 2 2 test/mpi_rocm.jl
 
   - label: Julia 1.11 (oneAPI, MPI)
@@ -96,7 +97,7 @@ steps:
     agents:
       queue: "oneapi"
     command: |
-      julia --project=test/oneapienv -e 'using Pkg; Pkg.develop(PackageSpec(path=pwd())); Pkg.instantiate()'
+      julia --project=test/oneapienv -e 'using Pkg; Pkg.develop([PackageSpec(path=pwd()), PackageSpec(path="lib/TimespanLogging")]); Pkg.instantiate()'
       julia --project=test/oneapienv test/run_mpi.jl 2 2 test/mpi_oneapi.jl
 
   - label: Julia 1.11 (Metal, MPI)
@@ -108,7 +109,7 @@ steps:
     agents:
       queue: "metal"
     command: |
-      julia --project=test/metalenv -e 'using Pkg; Pkg.develop(PackageSpec(path=pwd())); Pkg.instantiate()'
+      julia --project=test/metalenv -e 'using Pkg; Pkg.develop([PackageSpec(path=pwd()), PackageSpec(path="lib/TimespanLogging")]); Pkg.instantiate()'
       julia --project=test/metalenv test/run_mpi.jl 2 2 test/mpi_metal.jl
 
   - label: Julia 1.11 (Finch)

.github/workflows/CI.yml

@@ -131,7 +131,7 @@ jobs:
           arch: x64
       - uses: julia-actions/cache@v3
       - name: Test TimespanLogging
-        run: julia --project=. -e 'using Pkg; Pkg.instantiate(); Pkg.develop(;path="lib/TimespanLogging"); Pkg.test("TimespanLogging")'
+        run: julia --project=. -e 'using Pkg; Pkg.develop(;path="lib/TimespanLogging"); Pkg.instantiate(); Pkg.test("TimespanLogging")'
 
   daggerwebdash:
     name: Julia 1 - DaggerWebDash
@@ -146,7 +146,7 @@ jobs:
           arch: x64
       - uses: julia-actions/cache@v3
       - name: Test DaggerWebDash
-        run: julia -e 'using Pkg; Pkg.develop(;path=pwd()); Pkg.develop(;path="lib/TimespanLogging"); Pkg.develop(;path="lib/DaggerWebDash"); include("lib/DaggerWebDash/test/runtests.jl")'
+        run: julia -e 'using Pkg; Pkg.develop([PackageSpec(path=pwd()), PackageSpec(path="lib/TimespanLogging"), PackageSpec(path="lib/DaggerWebDash")]); include("lib/DaggerWebDash/test/runtests.jl")'
 
   benchmarks:
     name: Benchmarks (vs master)
@@ -437,7 +437,7 @@ jobs:
       # feature and is silently ignored on 1.10 (LTS), which would otherwise
       # resolve a stale registered Dagger lacking the MPI API (`accelerate!`).
       - name: Instantiate CPU MPI environment
-        run: julia --project=test/mpienv -e 'using Pkg; Pkg.develop(PackageSpec(path=pwd())); Pkg.instantiate()'
+        run: julia --project=test/mpienv -e 'using Pkg; Pkg.develop([PackageSpec(path=pwd()), PackageSpec(path="lib/TimespanLogging")]); Pkg.instantiate()'
       - name: Run CPU MPI tests
         run: julia --project=test/mpienv test/run_mpi.jl ${{ matrix.ranks }} 2 test/mpi.jl
 
@@ -462,6 +462,6 @@ jobs:
           arch: x64
       - uses: julia-actions/cache@v3
       - name: Instantiate OpenCL MPI environment
-        run: julia --project=test/openclenv -e 'using Pkg; Pkg.develop(PackageSpec(path=pwd())); Pkg.instantiate()'
+        run: julia --project=test/openclenv -e 'using Pkg; Pkg.develop([PackageSpec(path=pwd()), PackageSpec(path="lib/TimespanLogging")]); Pkg.instantiate()'
       - name: Run OpenCL MPI tests
         run: julia --project=test/openclenv test/run_mpi.jl 2 2 test/mpi_opencl.jl

AGENTS.md

@@ -294,3 +294,33 @@ lesson.
    and died in `ipc_export(::Matrix)`. Stamp the result from
    `value_memory_space`, and do not select IPC unless the chunktype is a
    GPU array (`ipc_type_eligible`). Space-only `ipc_eligible` is not enough.
+
+27. **Log emitters in tests must be count-bounded, and chunk lists must be
+   memory-bounded.** A `while !stop[]` logger on every default thread will
+   starve the task that flips `stop` (lesson 12) and allocate slabs until
+   the machine OOMs — measured at 250GB+ virtual across leftover
+   `Pkg.test` children after only the parent shell was killed. Use a
+   fixed `for i in 1:N` (N on the order of a few chunks), cap published
+   slabs (`MAX_CHUNKS`), and when killing a hung Julia test kill the
+   whole process group (`kill -- -$PGID`), not just the `julia -e`
+   wrapper. `Pkg.test` spawns a child that keeps running if you only
+   SIGTERM the wrapper.
+
+28. **`nworkers() == 1` means "this process", not "there are workers".**
+   Without `addprocs`, `workers() == [1]`. `remotecall_wait` /
+   `remotecall_fetch` to `myid()` deadlocks — the Distributed waiter
+   never runs on the calling task. Gate broadcasts with
+   `length(procs()) > 1` (then `workers()` are remote only; Dagger does
+   not import `nprocs`). `_map_workers` already calls `f()`
+   locally when `p == myid()`; do not reintroduce a self-remotecall
+   around `enable_logging!` / `get_logs!`.
+
+29. **Do not mutate TimespanLogging globals at another package's toplevel.**
+   `@logcategory` used to call `register_category!` while Dagger was
+   precompiling. Those writes land in TimespanLogging's arrays in the
+   *precompile process* and are discarded when TimespanLogging loads from
+   its own image; Dagger's baked `const` IDs then disagree with a fresh
+   runtime registry (or collide with MemPool/tests that register later).
+   Category IDs are assigned lazily on first `category_id` use. Keep it
+   that way — a `const ID = register_category!(...)` at Dagger toplevel
+   is not safe.

Project.toml

@@ -124,6 +124,6 @@ ScopedValues = "1.1"
 Statistics = "1"
 StatsBase = "0.28, 0.29, 0.30, 0.31, 0.32, 0.33, 0.34"
 TaskLocalValues = "0.1"
-TimespanLogging = "0.1.1"
+TimespanLogging = "0.2"
 julia = "1.10"
 oneAPI = "1, 2"

lib/DaggerWebDash/Project.toml

@@ -25,5 +25,5 @@ Mux = "0.7, 1"
 ProfileSVG = "0.2"
 StructTypes = "1"
 Tables = "1"
-TimespanLogging = "0.1"
+TimespanLogging = "0.1, 0.2"
 julia = "1.6"

lib/TimespanLogging/Project.toml

@@ -1,7 +1,7 @@
 name = "TimespanLogging"
 uuid = "a526e669-04d3-4846-9525-c66122c55f63"
 authors = ["Julian P Samaroo <jpsamaroo@jpsamaroo.me>"]
-version = "0.1.1"
+version = "0.2.0"
 
 [deps]
 Distributed = "8ba89e20-285c-5b6f-9357-94700520ee1b"

lib/TimespanLogging/bench/compare_datadeps.jl

@@ -0,0 +1,98 @@
+# Compare Datadeps matmul / cholesky: master vs this worktree, logging on vs off.
+# Run with: timeout 600 julia --startup-file=no lib/TimespanLogging/bench/compare_datadeps.jl
+
+const WORKTREE = abspath(joinpath(@__DIR__, "..", "..", ".."))
+# Same Dagger commit as this worktree, old TimespanLogging, Manifest
+# pinned to MemPool 0.4.18 (the live `Dagger` checkout's Manifest still
+# has 0.4.15, which cannot load current Dagger).
+const MASTER = get(ENV, "DAGGER_TSL_BASELINE", "/tmp/Dagger-tsl-baseline")
+const WORKLOAD = joinpath(@__DIR__, "workload.jl")
+const JULIA = Base.julia_cmd().exec[1]
+const NTHREADS = "4"
+const PROC_TIMEOUT = 240
+
+function run_one(label::String, dagger_path::String, logging::Bool)
+    isdir(dagger_path) || error("missing Dagger tree: $dagger_path")
+    script = """
+        include($(repr(WORKLOAD)))
+        results = run_workload($(logging))
+        print_results($(repr(label)), $(logging), results)
+    """
+    cmd = `timeout --kill-after=15 $(PROC_TIMEOUT) $(JULIA) --project=$(dagger_path) -t $(NTHREADS) --startup-file=no -e $(script)`
+    println(stderr, "running $(label) logging=$(logging) ...")
+    flush(stderr)
+    return read(cmd, String)
+end
+
+function parse_results(text::String)
+    rows = NamedTuple[]
+    for line in split(text, '\n')
+        startswith(line, "RESULT ") || continue
+        fields = Dict{String,String}()
+        for part in split(line[8:end], ' ')
+            k, v = split(part, '='; limit=2)
+            fields[k] = v
+        end
+        push!(rows, (
+            tree=fields["tree"],
+            logging=fields["logging"] == "true",
+            op=Symbol(fields["op"]),
+            time=parse(Float64, fields["time"]),
+            allocs=parse(Int, fields["allocs"]),
+            bytes=parse(Int, fields["bytes"]),
+        ))
+    end
+    return rows
+end
+
+function fmt_bytes(b)
+    b < 1024 && return "$(b) B"
+    b < 1024^2 && return string(round(b / 1024; digits=1), " KiB")
+    return string(round(b / 1024^2; digits=2), " MiB")
+end
+
+function main()
+    configs = (
+        ("master", MASTER, false),
+        ("master", MASTER, true),
+        ("worktree", WORKTREE, false),
+        ("worktree", WORKTREE, true),
+    )
+    rows = NamedTuple[]
+    for (label, path, logging) in configs
+        try
+            text = run_one(label, path, logging)
+            print(text)
+            append!(rows, parse_results(text))
+        catch err
+            @error "config failed" label logging exception=err
+        end
+    end
+    println()
+    println("Datadeps logging overhead (min of $(3) measured runs; N=512, B=64)")
+    println(rpad("tree", 10), rpad("log", 6), rpad("op", 10),
+            lpad("time (s)", 10), lpad("allocs", 12), lpad("bytes", 12))
+    println(repeat("-", 60))
+    for r in rows
+        println(rpad(r.tree, 10), rpad(string(r.logging), 6), rpad(string(r.op), 10),
+                lpad(string(round(r.time; digits=4)), 10),
+                lpad(string(r.allocs), 12),
+                lpad(fmt_bytes(r.bytes), 12))
+    end
+    println()
+    println("logging-on / logging-off")
+    for op in (:matmul, :cholesky)
+        for tree in ("master", "worktree")
+            off = findfirst(r -> r.tree == tree && !r.logging && r.op == op, rows)
+            on = findfirst(r -> r.tree == tree && r.logging && r.op == op, rows)
+            (off === nothing || on === nothing) && continue
+            a, b = rows[off], rows[on]
+            println(rpad(tree, 10), rpad(string(op), 10),
+                    " time×", round(b.time / a.time; digits=2),
+                    "  allocs×", round(b.allocs / a.allocs; digits=2),
+                    "  bytes×", round(b.bytes / a.bytes; digits=2))
+        end
+    end
+end
+
+main()

lib/TimespanLogging/bench/workload.jl

@@ -0,0 +1,69 @@
+# Bounded Datadeps workload used by compare_datadeps.jl.
+# Do not fetch_logs! here — we want emit-path overhead only.
+
+using Dagger
+using LinearAlgebra
+
+const N = 512
+const B = 64
+const WARMUP = 3
+const RUNS = 3
+
+function measure(f; warmup=WARMUP, runs=RUNS)
+    for _ in 1:warmup
+        f()
+    end
+    GC.gc()
+    best_t = Inf
+    best_a = typemax(Int)
+    best_b = typemax(Int)
+    for _ in 1:runs
+        t0 = time_ns()
+        before = Base.gc_num()
+        f()
+        dt = (time_ns() - t0) / 1e9
+        diff = Base.GC_Diff(Base.gc_num(), before)
+        best_t = min(best_t, dt)
+        best_a = min(best_a, Base.gc_alloc_count(diff))
+        best_b = min(best_b, Int(diff.allocd))
+    end
+    return (time=best_t, allocs=best_a, bytes=best_b)
+end
+
+function setup_logging!(on::Bool)
+    if on
+        Dagger.enable_logging!(;all_task_deps=true)
+    else
+        Dagger.disable_logging!()
+    end
+    return nothing
+end
+
+function run_workload(logging::Bool)
+    setup_logging!(logging)
+    A = rand(Blocks(B, B), Float64, N, N)
+    C = zeros(Blocks(B, B), Float64, N, N)
+    wait(A); wait(C)
+    matmul = measure() do
+        mul!(C, A, A)
+    end
+    G = rand(Blocks(B, B), Float64, N, N)
+    S = G * G'
+    wait(S)
+    chol = measure() do
+        wait(cholesky(S).factors)
+    end
+    return (matmul=matmul, cholesky=chol)
+end
+
+function print_results(label, logging, results)
+    for (op, r) in ((:matmul, results.matmul), (:cholesky, results.cholesky))
+        println("RESULT tree=", label,
+                " logging=", logging,
+                " op=", op,
+                " time=", r.time,
+                " allocs=", r.allocs,
+                " bytes=", r.bytes)
+    end
+    flush(stdout)
+end

lib/TimespanLogging/src/TimespanLogging.jl

@@ -1,6 +1,23 @@
 module TimespanLogging
 
-include("core.jl")
+export enable!, disable!, reset!, steal_typed, steal_legacy, steal_all_old_events
+export EventRecord, LegacyEvent, LogCategory, category_id, category_symbol, event_type
+export CHUNK_CAPACITY, MAX_CHUNKS, max_chunks, NoOpLog, ActiveLog, LocalEventLog, MultiEventLog
+
+include("types.jl")
+include("category.jl")
+include("buffer.jl")
+include("runtime.jl")
+include("emit.jl")
+include("collect.jl")
+include("compat.jl")
 include("extras.jl")
 
+function __init__()
+    GC_PLACEHOLDER[] = Base.gc_num()
+    n = max(Threads.maxthreadid(), 1)
+    THREAD_STATES[] = Vector{Union{ThreadState,Nothing}}(nothing, n)
+    return nothing
+end
+
 end # module