From 60878dda5b171efe7e612e2bc33de551863c52fb Mon Sep 17 00:00:00 2001 From: Julian P Samaroo Date: Tue, 14 Apr 2026 11:44:01 -0700 Subject: [PATCH 1/5] Add LinuxPerf metrics for logging --- Project.toml | 3 ++ ext/LinuxPerfExt.jl | 109 ++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 112 insertions(+) create mode 100644 ext/LinuxPerfExt.jl diff --git a/Project.toml b/Project.toml index e9b47d8b2..2cc37857a 100644 --- a/Project.toml +++ b/Project.toml @@ -40,6 +40,7 @@ DataFrames = "a93c6f00-e57d-5684-b7b6-d8193f3e46c0" Distributions = "31c24e10-a181-5473-b8eb-7969acd0382f" GraphViz = "f526b714-d49f-11e8-06ff-31ed36ee7ee0" JSON3 = "0f8b85d8-7281-11e9-16c2-39a750bddbf1" +LinuxPerf = "b4c46c6c-4fb0-484d-a11a-41bc3392d094" Metal = "dde4c033-4e86-420c-a63e-0dd931031962" OpenCL = "08131aa3-fb12-5dee-8b74-c09406e224a2" Plots = "91a5bcdd-55d7-5caf-9e0b-520d859cae80" @@ -54,6 +55,7 @@ GraphVizExt = "GraphViz" GraphVizSimpleExt = "Colors" IntelExt = "oneAPI" JSON3Ext = "JSON3" +LinuxPerfExt = "LinuxPerf" MetalExt = "Metal" OpenCLExt = "OpenCL" PlotsExt = ["DataFrames", "Plots"] @@ -76,6 +78,7 @@ GraphViz = "0.2" Graphs = "1" JSON3 = "1" KernelAbstractions = "0.9" +LinuxPerf = "0.4.2" MacroTools = "0.5" MemPool = "0.4.16" Metal = "1.1" diff --git a/ext/LinuxPerfExt.jl b/ext/LinuxPerfExt.jl new file mode 100644 index 000000000..91db8837d --- /dev/null +++ b/ext/LinuxPerfExt.jl @@ -0,0 +1,109 @@ +module LinuxPerfExt + +import Dagger +import LinuxPerf + +import TimespanLogging +import TimespanLogging: Event, init_similar + +const DEFAULT_METRIC_SPEC = + "cpu-clock, page-faults, context-switches, cpu-migrations, minor-faults, major-faults" + +mutable struct LinuxPerfMetrics + # Perf-style grouping string, e.g. "(cpu-cycles,instructions), page-faults" + metric_spec::String + # Lazily constructed bench; metric names are read from bench.groups[*].event_types + bench::Union{Nothing, LinuxPerf.PerfBench} + # One atomic refcount per EventGroup: enable on 0->1, disable on 1->0 + refcounts::Vector{Threads.Atomic{Int}} + # Baseline counter snapshots per active event, keyed by (category, id) + active_baselines::Dict{Any, Vector{UInt64}} +end + +LinuxPerfMetrics(spec::String) = + LinuxPerfMetrics(spec, nothing, Threads.Atomic{Int}[], Dict{Any,Vector{UInt64}}()) +LinuxPerfMetrics() = LinuxPerfMetrics(DEFAULT_METRIC_SPEC) +init_similar(m::LinuxPerfMetrics) = LinuxPerfMetrics(m.metric_spec) + +# Build the PerfBench from the metric spec string on first use. +function _ensure_bench!(metrics::LinuxPerfMetrics) + if metrics.bench === nothing + groups_spec = LinuxPerf.parse_groups(metrics.metric_spec) + event_groups = LinuxPerf.EventGroup[LinuxPerf.EventGroup(g) for g in groups_spec] + metrics.bench = LinuxPerf.PerfBench(0, event_groups) + metrics.refcounts = [Threads.Atomic{Int}(0) for _ in event_groups] + end + return metrics.bench +end + +# Read raw counter values from every group, ordered group-by-group. +# Read format per group: [nr, time_enabled, time_running, value_1, ..., value_nr] +function _read_raw_counters(bench::LinuxPerf.PerfBench) + vals = UInt64[] + for g in bench.groups + g.leader_fd == -1 && continue + buf = Vector{UInt64}(undef, length(g) + 3) + read!(g.leader_io, buf) + for i in 1:length(g) + push!(vals, buf[3 + i]) + end + end + return vals +end + +# Subtract baseline from current snapshot; build name->delta dict using +# metric names sourced from the bench's EventGroup event_types. +function _delta_to_dict(bench::LinuxPerf.PerfBench, baseline::Vector{UInt64}) + current = _read_raw_counters(bench) + result = Dict{String, Int64}() + idx = 1 + for g in bench.groups + g.leader_fd == -1 && continue + for et in g.event_types + name = get(LinuxPerf.EVENT_TO_NAME, et, string(et)) + result[name] = Int64(current[idx] - baseline[idx]) + idx += 1 + end + end + return result +end + +function (metrics::LinuxPerfMetrics)(ev::Event{:start}) + bench = _ensure_bench!(metrics) + isempty(bench.groups) && return nothing + + # Enable each group on the 0->1 transition only + for (group, rc) in zip(bench.groups, metrics.refcounts) + old = Threads.atomic_add!(rc, 1) + if old == 0 + LinuxPerf.reset!(group) + LinuxPerf.enable!(group) + end + end + + metrics.active_baselines[(ev.category, ev.id)] = _read_raw_counters(bench) + nothing +end + +function (metrics::LinuxPerfMetrics)(ev::Event{:finish}) + bench = metrics.bench + bench === nothing && return nothing + + baseline = pop!(metrics.active_baselines, (ev.category, ev.id), nothing) + baseline === nothing && return nothing + + # Read delta before potentially disabling any group + result = _delta_to_dict(bench, baseline) + + # Disable each group on the 1->0 transition only + for (group, rc) in zip(bench.groups, metrics.refcounts) + old = Threads.atomic_sub!(rc, 1) + if old == 1 + LinuxPerf.disable!(group) + end + end + + return result +end + +end # module LinuxPerfExt From 8d2c86b6ae0f9d65a77f4f817b008e1e89c41310 Mon Sep 17 00:00:00 2001 From: Julian P Samaroo Date: Tue, 14 Apr 2026 11:44:54 -0700 Subject: [PATCH 2/5] logging: Add GC, compile time, LinuxPerf metrics to enable_logging --- docs/src/api-dagger/types.md | 3 ++ docs/src/logging.md | 36 +++++++++++++++ src/utils/logging-events.jl | 90 ++++++++++++++++++++++++++++++++++++ src/utils/logging.jl | 31 ++++++++++++- test/Project.toml | 1 + test/logging.jl | 38 +++++++++++++++ 6 files changed, 198 insertions(+), 1 deletion(-) diff --git a/docs/src/api-dagger/types.md b/docs/src/api-dagger/types.md index 4e6d0460e..fd1c5c60c 100644 --- a/docs/src/api-dagger/types.md +++ b/docs/src/api-dagger/types.md @@ -69,4 +69,7 @@ UnitDomain Events.BytesAllocd Events.ProcessorSaturation Events.WorkerSaturation +Events.GCStats +Events.LockContentionMetrics +Events.CompileTimeMetrics ``` diff --git a/docs/src/logging.md b/docs/src/logging.md index a5e5ebd51..67c059d76 100644 --- a/docs/src/logging.md +++ b/docs/src/logging.md @@ -32,3 +32,39 @@ Dagger.disable_logging!() ``` For more advanced logging configurations, such as custom log sinks and consumers, see [Logging: Advanced](@ref). + +## Performance Metrics + +`enable_logging!` accepts a variety of keyword arguments to enable additional +per-event metrics beyond the always-on core events; see the `enable_logging!` +docstring for the full list. A few notable ones for performance analysis are: + +- `gc_stats::Bool`: Records the number of bytes allocated by the GC during each event. +- `lock_contend::Bool`: Records the number of lock conflicts (contended lock acquisitions) that occurred during each event. +- `compile_time::Bool`: Records how much time was spent in Julia's compiler during each event. +- `linuxperf::String`: Records hardware/software performance counters (via [LinuxPerf.jl](https://github.com/JuliaPerf/LinuxPerf.jl)) for each event, on Linux systems. + +The `linuxperf` argument takes a perf-style event/group specification string +(the same format accepted by `LinuxPerf.parse_groups`), such as +`"cpu-clock, page-faults, (cpu-cycles,instructions)"`. `LinuxPerf.jl` must be +loaded (`using LinuxPerf`) before passing a non-empty `linuxperf` argument, +otherwise an error will be thrown: + +```julia +using Dagger, LinuxPerf + +Dagger.enable_logging!(;linuxperf="cpu-clock, page-faults, cache-misses", + gc_stats=true, lock_contend=true, compile_time=true) + +wait(Dagger.@spawn sum([1, 2, 3])) + +logs = Dagger.fetch_logs!() +Dagger.disable_logging!() + +# logs[1][:linuxperf] contains a `Dict{String,Int64}` of counter deltas for +# each finished event; logs[1][:gc_stats], logs[1][:lock_contend], and +# logs[1][:compile_time] contain per-event scalar values. +``` + +These metrics are also picked up automatically by the `:summary` text +visualizer; see [Logging: Visualization](logging-visualization.md) for details. diff --git a/src/utils/logging-events.jl b/src/utils/logging-events.jl index 344a42da5..a515e777b 100644 --- a/src/utils/logging-events.jl +++ b/src/utils/logging-events.jl @@ -276,4 +276,94 @@ function (::TaskToChunk)(ev::Event{:finish}) return end +""" + GCStats + +Tracks GC allocations (`Base.GC_Diff.allocd`) between the start and finish of +each event, using the `gc_num` field already captured in each `Event`. +""" +mutable struct GCStats + active_starts::Dict{Any, Base.GC_Num} +end +GCStats() = GCStats(Dict{Any, Base.GC_Num}()) +init_similar(::GCStats) = GCStats() + +function (gs::GCStats)(ev::Event{:start}) + gs.active_starts[(ev.category, ev.id)] = ev.gc_num + nothing +end +function (gs::GCStats)(ev::Event{:finish}) + start_gc = pop!(gs.active_starts, (ev.category, ev.id), nothing) + start_gc === nothing && return nothing + return Base.GC_Diff(ev.gc_num, start_gc).allocd +end + +const _lock_contention_refcount = Threads.Atomic{Int}(0) + +""" + LockContentionMetrics + +Tracks the number of lock contention events between the start and finish of +each event. Uses a global atomic refcount to enable/disable +`Base.Threads.lock_profiling` only while at least one event is in-flight. +""" +mutable struct LockContentionMetrics + active_starts::Dict{Any, Int64} +end +LockContentionMetrics() = LockContentionMetrics(Dict{Any, Int64}()) +init_similar(::LockContentionMetrics) = LockContentionMetrics() + +function (lc::LockContentionMetrics)(ev::Event{:start}) + old = Threads.atomic_add!(_lock_contention_refcount, 1) + if old == 0 + Base.Threads.lock_profiling(true) + end + lc.active_starts[(ev.category, ev.id)] = Int64(Base.Threads.LOCK_CONFLICT_COUNT[]) + nothing +end +function (lc::LockContentionMetrics)(ev::Event{:finish}) + baseline = pop!(lc.active_starts, (ev.category, ev.id), nothing) + baseline === nothing && return nothing + current = Int64(Base.Threads.LOCK_CONFLICT_COUNT[]) + old = Threads.atomic_sub!(_lock_contention_refcount, 1) + if old == 1 + Base.Threads.lock_profiling(false) + end + return current - baseline +end + +const _compile_timing_refcount = Threads.Atomic{Int}(0) + +""" + CompileTimeMetrics + +Tracks cumulative Julia compile time (via `Base.cumulative_compile_time_ns`) +between the start and finish of each event. Uses a global atomic refcount to +enable/disable timing only while at least one event is in-flight. +""" +mutable struct CompileTimeMetrics + active_starts::Dict{Any, Int64} +end +CompileTimeMetrics() = CompileTimeMetrics(Dict{Any, Int64}()) +init_similar(::CompileTimeMetrics) = CompileTimeMetrics() + +function (ct::CompileTimeMetrics)(ev::Event{:start}) + old = Threads.atomic_add!(_compile_timing_refcount, 1) + if old == 0 + Base.cumulative_compile_timing(true) + end + ct.active_starts[(ev.category, ev.id)] = Int64(Base.cumulative_compile_time_ns()[1]) + nothing +end +function (ct::CompileTimeMetrics)(ev::Event{:finish}) + baseline = pop!(ct.active_starts, (ev.category, ev.id), nothing) + baseline === nothing && return nothing + current = Int64(Base.cumulative_compile_time_ns()[1]) + old = Threads.atomic_sub!(_compile_timing_refcount, 1) + if old == 1 + Base.cumulative_compile_timing(false) + end + return current - baseline +end + end # module Events diff --git a/src/utils/logging.jl b/src/utils/logging.jl index 1b1f09abd..6466bff9a 100644 --- a/src/utils/logging.jl +++ b/src/utils/logging.jl @@ -18,6 +18,10 @@ Extra events: - `taskuidtotid::Bool`: Enables reporting of task UID-to-TID mappings - `tasktochunk::Bool`: Enables reporting of DTask-to-Chunk mappings - `profile::Bool`: Enables profiling of task execution; not currently recommended, as it adds significant overhead +- `linuxperf::String`: Enables Linux perf event collection of the specified events (requires LinuxPerf.jl to be loaded) +- `gc_stats::Bool`: Enables GC allocation tracking per event +- `lock_contend::Bool`: Enables lock contention counting per event +- `compile_time::Bool`: Enables Julia compile-time tracking per event """ function enable_logging!(;metrics::Bool=false, timeline::Bool=false, @@ -30,7 +34,11 @@ function enable_logging!(;metrics::Bool=false, taskresult::Bool=false, taskuidtotid::Bool=false, tasktochunk::Bool=false, - profile::Bool=false) + profile::Bool=false, + linuxperf::String="", + gc_stats::Bool=false, + lock_contend::Bool=false, + compile_time::Bool=false) ml = TimespanLogging.MultiEventLog() ml[:core] = TimespanLogging.Events.CoreMetrics() ml[:id] = TimespanLogging.Events.IDMetrics() @@ -81,10 +89,31 @@ function enable_logging!(;metrics::Bool=false, ml[:esat] = TimespanLogging.Events.EventSaturation() ml[:psat] = Dagger.Events.ProcessorSaturation() end + if !isempty(linuxperf) + lp = _make_linuxperf_metrics(linuxperf) + if lp !== nothing + ml[:linuxperf] = lp + end + end + if gc_stats + ml[:gc_stats] = Dagger.Events.GCStats() + end + if lock_contend + ml[:lock_contend] = Dagger.Events.LockContentionMetrics() + end + if compile_time + ml[:compile_time] = Dagger.Events.CompileTimeMetrics() + end Dagger.Sch.eager_context().log_sink = ml return end +function _make_linuxperf_metrics(metrics::String) + ext = Base.get_extension(Dagger, :LinuxPerfExt) + ext === nothing && throw(ErrorException("LinuxPerf.jl is not loaded")) + return ext.LinuxPerfMetrics(metrics) +end + """ disable_logging!() diff --git a/test/Project.toml b/test/Project.toml index a1a112875..f0d439625 100644 --- a/test/Project.toml +++ b/test/Project.toml @@ -12,6 +12,7 @@ Graphs = "86223c79-3864-5bf0-83f7-82e725a168b6" JSON3 = "0f8b85d8-7281-11e9-16c2-39a750bddbf1" KernelAbstractions = "63c18a36-062a-441e-b654-da1e3ab1ce7c" LinearAlgebra = "37e2e46d-f89d-539d-b4ee-838fcccc9c8e" +LinuxPerf = "b4c46c6c-4fb0-484d-a11a-41bc3392d094" MemPool = "f9f48841-c794-520a-933b-121f7ba6ed94" OnlineStats = "a15396b6-48d5-5d58-9928-6d29437db91e" Pkg = "44cfe95a-1eb2-52ea-b672-e2afdf69b78f" diff --git a/test/logging.jl b/test/logging.jl index fcd4c64d0..054f576b3 100644 --- a/test/logging.jl +++ b/test/logging.jl @@ -1,6 +1,9 @@ import TimespanLogging import TimespanLogging: Timespan, Event, Events, LocalEventLog, MultiEventLog import Colors, GraphViz, DataFrames, Plots, JSON3 +if Sys.islinux() + import LinuxPerf +end @testset "Logging" begin @testset "LocalEventLog" begin @@ -65,6 +68,41 @@ import Colors, GraphViz, DataFrames, Plots, JSON3 Dagger.disable_logging!() end + @testset "enable_logging! (GC/lock/compile-time metrics)" begin + Dagger.enable_logging!(;gc_stats=true, lock_contend=true, compile_time=true) + + t = Dagger.@spawn 1+2 + fetch(Dagger.@spawn t*3) + + logs = Dagger.fetch_logs!() + @test haskey(logs, 1) + for consumer in (:gc_stats, :lock_contend, :compile_time) + @test length(logs[1][consumer]) > 0 + @test any(x->x !== nothing, logs[1][consumer]) + end + + Dagger.disable_logging!() + end + + if Sys.islinux() + @testset "enable_logging! (LinuxPerf)" begin + Dagger.enable_logging!(;linuxperf="cpu-clock, page-faults") + + t = Dagger.@spawn 1+2 + fetch(Dagger.@spawn t*3) + + logs = Dagger.fetch_logs!() + @test haskey(logs, 1) + @test haskey(logs[1], :linuxperf) + @test length(logs[1][:linuxperf]) > 0 + @test any(x->x isa Dict, logs[1][:linuxperf]) + @test any(x->x isa Dict && haskey(x, "cpu-clock") && haskey(x, "page-faults"), + logs[1][:linuxperf]) + + Dagger.disable_logging!() + end + end + @testset "Manual" begin ctx = Context() ml = MultiEventLog() From 7e3c0d60b36526230f4439c59cdf46b3157c9ec6 Mon Sep 17 00:00:00 2001 From: Julian P Samaroo Date: Tue, 14 Apr 2026 11:46:04 -0700 Subject: [PATCH 3/5] viz: Add :summary text visualizer to show_logs --- docs/src/logging-visualization.md | 48 ++++++++ src/utils/viz.jl | 178 ++++++++++++++++++++++++++++++ test/logging.jl | 19 ++++ 3 files changed, 245 insertions(+) diff --git a/docs/src/logging-visualization.md b/docs/src/logging-visualization.md index 346bdbdd6..6e0c96039 100644 --- a/docs/src/logging-visualization.md +++ b/docs/src/logging-visualization.md @@ -21,11 +21,59 @@ converted to a `Val` for dispatch purposes Built-in `IO` support exists for: - `show_logs(io, logs, :graphviz)` to write a Graphviz dot graph of executed tasks and their dependencies (requires `GraphViz.jl` to be loaded) - `show_logs(io, logs, :chrome_trace)` to write a task execution timeline in the chrome-trace format (view in [perfetto web UI](https://ui.perfetto.dev/) or `about:tracing` in a chrome-based browser) (requires `JSON3.jl` to be loaded) +- `show_logs(io, logs, :summary)` to print a plain-text summary of per-category event statistics (no extra packages required) Built-in rendering support exists for: - `render_logs(logs, :graphviz)` to generate a graph diagram of executed tasks and their dependencies (requires `GraphViz.jl` to be loaded) - `render_logs(logs, :plots_gantt)` to generate a Gantt chart of task execution across all processors (requires `Plots.jl` and `DataFrames.jl` to be loaded) +### Text summaries with show_logs(..., :summary) + +The `:summary` mode prints, for every event category (`:compute`, `:move`, +`:schedule`, etc.), the mean/min/max run time across all recorded events of +that category. If enabled via `enable_logging!`, it also reports mean/min/max +of any additional per-event metrics that were collected: `LinuxPerf.jl` +counters (`linuxperf`), GC bytes allocated (`gc_stats`), lock conflicts +(`lock_contend`), and Julia compile time (`compile_time`); see +[Logging: Basics](logging.md) for more on these metrics. For the +`:compute` and `:move` categories, statistics are additionally broken down +per task function name. + +```julia +using Dagger + +Dagger.enable_logging!(;all_task_deps=true, gc_stats=true, lock_contend=true, compile_time=true) + +wait(Dagger.@spawn sum([1, 2, 3])) + +logs = Dagger.fetch_logs!() +Dagger.disable_logging!() + +# Print directly to stdout +Dagger.show_logs(logs, :summary) + +# Or write to any IO, such as a file or IOBuffer +open("summary.txt", "w") do io + Dagger.show_logs(io, logs, :summary) +end +``` + +This produces output similar to: + +``` +=== Dagger Execution Summary === + +[compute] 2 events, 2 unique task(s) + Run Time mean=31.1 us, min=7.0 us, max=55.3 us + Bytes Allocated mean=1.2 MiB, min=219.7 KiB, max=2.2 MiB + Compile Time mean=37.5 us, min=9.8 us, max=65.2 us + Lock Conflicts mean=0, min=0, max=0 + + [compute :: +] 1 events + Run Time mean=55.3 us, min=55.3 us, max=55.3 us + ... +``` + ## Continuous visualization with MultiEventLog The `MultiEventLog` mechanism is designed for continuous rendering of logs as they are generated, which permits real-time visualization of Dagger's operations. This diff --git a/src/utils/viz.jl b/src/utils/viz.jl index 605d5655d..3fe06b5b2 100644 --- a/src/utils/viz.jl +++ b/src/utils/viz.jl @@ -419,4 +419,182 @@ function logs_to_dot(logs::Dict; disconnected=false, show_data::Bool=true, return str end + +# ---- :summary backend ---- + +# Override the default string-returning dispatch so :summary prints to stdout +function show_logs(logs::Dict, ::Val{:summary}; options...) + show_logs(stdout, logs, Val{:summary}(); options...) +end + +function pretty_bytes(n; digits=3) + r(x) = round(x; digits) + s = n < 0 ? "-" : "" + a = abs(n) + if a >= 1024^3 + "$(s)$(r(a/1024^3)) GiB" + elseif a >= 1024^2 + "$(s)$(r(a/1024^2)) MiB" + elseif a >= 1024 + "$(s)$(r(a/1024)) KiB" + else + "$(s)$(r(a)) B" + end +end + +""" + show_logs(io::IO, logs::Dict, ::Val{:summary}) + +Print a text summary of event statistics to `io` (default: stdout). + +For every event category, shows mean/min/max of: +- Run Time (wall-clock duration of the event) +- Each LinuxPerf metric (if `linuxperf=true` was passed to `enable_logging!`) +- Bytes Allocated (if `gc_stats=true`) +- Lock Conflicts (if `lock_contend=true`) +- Compile Time (if `compile_time=true`) + +For `:compute` and `:move` categories, the summary is additionally broken +down by task function name. +""" +function show_logs(io::IO, logs::Dict, ::Val{:summary}) + # Build thunk_id -> function name from :add_thunk/:start events + tid_to_fn = Dict{Int, String}() + for w in keys(logs) + haskey(logs[w], :taskfuncnames) || continue + for idx in 1:length(logs[w][:core]) + core = logs[w][:core][idx] + core.category == :add_thunk && core.kind == :start || continue + fn = logs[w][:taskfuncnames][idx] + fn isa String || continue + id = logs[w][:id][idx] + id === nothing && continue + tid_to_fn[id.thunk_id::Int] = fn + end + end + + # Channels that produce a scalar Int/Float value at the :finish event, + # mapped to their display name. Linuxperf is handled separately (it + # returns a Dict at :finish rather than a scalar). + scalar_channels = ( + (:compile_time, "Compile Time"), + (:lock_contend, "Lock Conflicts"), + (:gc_stats, "Bytes Allocated"), + ) + + # Accumulate samples keyed by (category, fn_or_nothing). + # Each bucket holds runtimes plus a generic extras dict for all other metrics. + buckets = Dict{Tuple{Symbol,Union{Nothing,String}}, + @NamedTuple{runtimes::Vector{Float64}, + extras::Dict{String,Vector{Float64}}}}() + + function get_bucket(cat, fn) + get!(buckets, (cat, fn)) do + (runtimes=Float64[], extras=Dict{String,Vector{Float64}}()) + end + end + + for w in keys(logs) + running = Dict{Any,Int}() # event key -> start idx + for idx in 1:length(logs[w][:core]) + core = logs[w][:core][idx] + id = logs[w][:id][idx] + id === nothing && continue + ekey = (core.category, id) + if core.kind == :start + running[ekey] = idx + elseif haskey(running, ekey) + start_idx = pop!(running, ekey) + runtime = Float64(core.timestamp - logs[w][:core][start_idx].timestamp) + + # Collect all extra metric values at the finish index + extra = Dict{String,Float64}() + + # LinuxPerf Dict + if haskey(logs[w], :linuxperf) + lp = logs[w][:linuxperf][idx] + if lp isa Dict + for (k, v) in lp + extra[k] = Float64(v) + end + end + end + + # Scalar channels + for (chan, dname) in scalar_channels + if haskey(logs[w], chan) + v = logs[w][chan][idx] + if v isa Number + extra[dname] = Float64(v) + end + end + end + + fn = nothing + if core.category in (:compute, :move) + try; fn = get(tid_to_fn, id.thunk_id, nothing); catch; end + end + + for bucket_fn in (fn === nothing ? (nothing,) : (nothing, fn)) + b = get_bucket(core.category, bucket_fn) + push!(b.runtimes, runtime) + for (k, v) in extra + push!(get!(Vector{Float64}, b.extras, k), v) + end + end + end + end + end + + isempty(buckets) && (println(io, "(no events recorded)"); return) + + # Formatting helpers + function fmt_stats(vals::Vector{Float64}, fmt_fn) + isempty(vals) && return "N/A" + μ = sum(vals) / length(vals) + "mean=$(fmt_fn(μ)), min=$(fmt_fn(minimum(vals))), max=$(fmt_fn(maximum(vals)))" + end + fmt_count(x) = string(round(Int, x)) + # Metric name -> formatter + time_metric_names = Set(("cpu-clock", "task-clock", "Compile Time")) + bytes_metric_names = Set(("Bytes Allocated",)) + metric_fmt(name) = + name in time_metric_names ? pretty_time : + name in bytes_metric_names ? pretty_bytes : + fmt_count + + function print_bucket_stats(b, indent::String) + # Target total column = 20; always leave at least 2 spaces after the name + target_col = max(20 - length(indent), 2) + all_names = ["Run Time"; collect(keys(b.extras))] + col = max(target_col, maximum(length, all_names; init=0) + 2) + println(io, "$(indent)$(rpad("Run Time", col))$(fmt_stats(b.runtimes, pretty_time))") + for (mname, mvals) in sort!(collect(b.extras), by=x->x[1]) + println(io, "$(indent)$(rpad(mname, col))$(fmt_stats(mvals, metric_fmt(mname)))") + end + end + + println(io, "=== Dagger Execution Summary ===") + + categories = sort!(unique(k[1] for k in keys(buckets)), by=string) + for cat in categories + b_all = get(buckets, (cat, nothing), nothing) + b_all === nothing && continue + n = length(b_all.runtimes) + + fn_keys = sort!([k[2] for k in keys(buckets) if k[1] == cat && k[2] !== nothing]) + fn_suffix = isempty(fn_keys) ? "" : ", $(length(fn_keys)) unique task(s)" + + println(io, "\n[$cat] $n events$fn_suffix") + print_bucket_stats(b_all, " ") + + cat in (:compute, :move) || continue + for fn in fn_keys + b = buckets[(cat, fn)] + println(io, "\n [$cat :: $fn] $(length(b.runtimes)) events") + print_bucket_stats(b, " ") + end + end +end + end # module Viz diff --git a/test/logging.jl b/test/logging.jl index 054f576b3..ee89ec733 100644 --- a/test/logging.jl +++ b/test/logging.jl @@ -225,4 +225,23 @@ end Dagger.disable_logging!() end + + @testset "show_logs :summary" begin + extra_kwargs = Sys.islinux() ? (;linuxperf="cpu-clock, page-faults") : NamedTuple() + Dagger.enable_logging!(;all_task_deps=true, gc_stats=true, lock_contend=true, + compile_time=true, extra_kwargs...) + + A = distribute(rand(4, 4), Blocks(8, 8)) + sum(A) + logs = Dagger.fetch_logs!() + Dagger.disable_logging!() + + io = IOBuffer() + Dagger.show_logs(io, logs, :summary) + seek(io, 0) + str = String(take!(io)) + @test !isempty(str) + @test occursin("Dagger Execution Summary", str) + @test occursin("Run Time", str) + end end From cc36b0b2fa789a73f9571fa0269e3e702f493672 Mon Sep 17 00:00:00 2001 From: Julian P Samaroo Date: Mon, 6 Jul 2026 08:07:47 -0700 Subject: [PATCH 4/5] test/logging: Disable LinuxPerf tests --- test/logging.jl | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/test/logging.jl b/test/logging.jl index ee89ec733..58845ba3b 100644 --- a/test/logging.jl +++ b/test/logging.jl @@ -1,9 +1,11 @@ import TimespanLogging import TimespanLogging: Timespan, Event, Events, LocalEventLog, MultiEventLog import Colors, GraphViz, DataFrames, Plots, JSON3 +#= if Sys.islinux() import LinuxPerf end +=# @testset "Logging" begin @testset "LocalEventLog" begin @@ -84,6 +86,7 @@ end Dagger.disable_logging!() end + #= Perf events aren't reliably enabled on CI if Sys.islinux() @testset "enable_logging! (LinuxPerf)" begin Dagger.enable_logging!(;linuxperf="cpu-clock, page-faults") @@ -102,6 +105,7 @@ end Dagger.disable_logging!() end end + =# @testset "Manual" begin ctx = Context() @@ -227,9 +231,9 @@ end end @testset "show_logs :summary" begin - extra_kwargs = Sys.islinux() ? (;linuxperf="cpu-clock, page-faults") : NamedTuple() + #extra_kwargs = Sys.islinux() ? (;linuxperf="cpu-clock, page-faults") : NamedTuple() Dagger.enable_logging!(;all_task_deps=true, gc_stats=true, lock_contend=true, - compile_time=true, extra_kwargs...) + compile_time=true)#, extra_kwargs...) A = distribute(rand(4, 4), Blocks(8, 8)) sum(A) From 28bae8481d18ba96f9d81ba3b88c42a9d951d01b Mon Sep 17 00:00:00 2001 From: Julian P Samaroo Date: Mon, 6 Jul 2026 08:11:49 -0700 Subject: [PATCH 5/5] logging: Lock contention not available on Julia 1.10 --- src/utils/logging-events.jl | 2 ++ src/utils/logging.jl | 3 +++ test/logging.jl | 13 ++++++++++--- 3 files changed, 15 insertions(+), 3 deletions(-) diff --git a/src/utils/logging-events.jl b/src/utils/logging-events.jl index a515e777b..452247c01 100644 --- a/src/utils/logging-events.jl +++ b/src/utils/logging-events.jl @@ -306,6 +306,8 @@ const _lock_contention_refcount = Threads.Atomic{Int}(0) Tracks the number of lock contention events between the start and finish of each event. Uses a global atomic refcount to enable/disable `Base.Threads.lock_profiling` only while at least one event is in-flight. + +Only supported on Julia 1.11+ """ mutable struct LockContentionMetrics active_starts::Dict{Any, Int64} diff --git a/src/utils/logging.jl b/src/utils/logging.jl index 6466bff9a..a431bd9eb 100644 --- a/src/utils/logging.jl +++ b/src/utils/logging.jl @@ -99,6 +99,9 @@ function enable_logging!(;metrics::Bool=false, ml[:gc_stats] = Dagger.Events.GCStats() end if lock_contend + if VERSION < v"1.11-" + throw(ArgumentError("Lock contention metrics are only supported on Julia 1.11+")) + end ml[:lock_contend] = Dagger.Events.LockContentionMetrics() end if compile_time diff --git a/test/logging.jl b/test/logging.jl index 58845ba3b..92f1dab32 100644 --- a/test/logging.jl +++ b/test/logging.jl @@ -71,14 +71,20 @@ end end @testset "enable_logging! (GC/lock/compile-time metrics)" begin - Dagger.enable_logging!(;gc_stats=true, lock_contend=true, compile_time=true) + lock_contend_supported = VERSION >= v"1.11-" + Dagger.enable_logging!(;gc_stats=true, lock_contend=lock_contend_supported, compile_time=true) t = Dagger.@spawn 1+2 fetch(Dagger.@spawn t*3) logs = Dagger.fetch_logs!() @test haskey(logs, 1) - for consumer in (:gc_stats, :lock_contend, :compile_time) + consumers = [:gc_stats] + if lock_contend_supported + push!(consumers, :lock_contend) + end + push!(consumers, :compile_time) + for consumer in consumers @test length(logs[1][consumer]) > 0 @test any(x->x !== nothing, logs[1][consumer]) end @@ -232,7 +238,8 @@ end @testset "show_logs :summary" begin #extra_kwargs = Sys.islinux() ? (;linuxperf="cpu-clock, page-faults") : NamedTuple() - Dagger.enable_logging!(;all_task_deps=true, gc_stats=true, lock_contend=true, + lock_contend_supported = VERSION >= v"1.11-" + Dagger.enable_logging!(;all_task_deps=true, gc_stats=true, lock_contend=lock_contend_supported, compile_time=true)#, extra_kwargs...) A = distribute(rand(4, 4), Blocks(8, 8))