From cf1884842aa21e2351eacce2cc1c8089d4dd5be1 Mon Sep 17 00:00:00 2001 From: Valentin Churavy Date: Sun, 4 Oct 2026 09:48:55 +0200 Subject: [PATCH] Time kernels on the device without synchronizing (prototype) Adds optional KernelInterface hooks, `record_timestamp(backend)` and `elapsed_time(backend, start, stop)`, with a fallback that reports no support. Tracers that set `records_kernels` get a `KernelTimer` for every launch, with timestamps recorded around the native enqueue alone, so compilation isn't counted. On backends without timestamps the launch synchronizes and is timed on the host instead. `@profile` uses this by default (`device = true`), resolving the timestamps once the profiled expression has run, and reports host-side and device-side activity separately. Launches no longer synchronize by default. Assisted-by: Claude Code (Opus 5.5) --- lib/KernelInterface/src/KernelInterface.jl | 1 + lib/KernelInterface/src/host.jl | 30 +++ src/KernelAbstractions.jl | 2 +- src/backend_launch.jl | 18 +- src/profiler.jl | 201 +++++++++++++++------ src/profiling.jl | 86 +++++++++ test/runtests.jl | 31 +++- 7 files changed, 304 insertions(+), 65 deletions(-) diff --git a/lib/KernelInterface/src/KernelInterface.jl b/lib/KernelInterface/src/KernelInterface.jl index 0f0fade1a..fcf2cb5d9 100644 --- a/lib/KernelInterface/src/KernelInterface.jl +++ b/lib/KernelInterface/src/KernelInterface.jl @@ -39,6 +39,7 @@ include("host.jl") # host side :allocate, :zeros, :ones, :copyto!, :pagelock!, :unsafe_free!, :synchronize, :record_event, :wait_event, :priority!, + :record_timestamp, :elapsed_time, :device, :ndevices, :device!, :functional, :versioninfo, :supports_unified, :supports_atomics, :supports_float64, diff --git a/lib/KernelInterface/src/host.jl b/lib/KernelInterface/src/host.jl index b769783cd..d9d5390f0 100644 --- a/lib/KernelInterface/src/host.jl +++ b/lib/KernelInterface/src/host.jl @@ -379,3 +379,33 @@ block until it has completed. For a simple, synchronous copy, use `Base.copyto!` device-to-device copies. """ function copyto! end + +""" + record_timestamp(backend::Backend) + +Enqueue a timestamp on the calling task's queue of `backend`'s active device, without +blocking, and return a handle for [`elapsed_time`](@ref). Returns `nothing` if the backend +doesn't support timestamps. + +Profilers use this to measure the device time of kernels without synchronizing the host +with the device. + +!!! note + Backend implementations **may** implement this function, e.g. with a CUDA event that + records timing. The fallback returns `nothing`. +""" +record_timestamp(::Backend) = nothing + +""" + elapsed_time(backend::Backend, start, stop)::Int64 + +The device time in nanoseconds between the timestamps `start` and `stop`, returned by +[`record_timestamp`](@ref) on the same device. Waits for `stop` to be reached, as +cooperatively as [`synchronize`](@ref) does. The result may be negative if `stop` was +reached before `start`, e.g. when they were recorded on different queues. + +!!! note + Backend implementations **must** implement this function if they implement + [`record_timestamp`](@ref). +""" +function elapsed_time end diff --git a/src/KernelAbstractions.jl b/src/KernelAbstractions.jl index cbada2d55..faac5e669 100644 --- a/src/KernelAbstractions.jl +++ b/src/KernelAbstractions.jl @@ -665,6 +665,7 @@ automatically when a kernel is launched. argconvert(k::Kernel{T}, arg) where {T} = error("Don't know how to convert arguments for Kernel{$T}") +include("profiling.jl") include("backend_launch.jl") # Enzyme support @@ -743,7 +744,6 @@ number as its compute units: `KernelAbstractions.POCL.device().max_compute_units """ const CPU = POCLBackend -include("profiling.jl") include("profiler.jl") include("precompile.jl") diff --git a/src/backend_launch.jl b/src/backend_launch.jl index 68081a5e3..83fb14da0 100644 --- a/src/backend_launch.jl +++ b/src/backend_launch.jl @@ -93,12 +93,22 @@ end Base.@nospecializeinfer @noinline function launch_traced( @nospecialize(obj::Kernel), @nospecialize(args::Tuple), @nospecialize(ndrange), @nospecialize(workgroupsize) ) - id = start_launch_range(kernel_label(obj.f)) + label = kernel_label(obj.f) + id = start_launch_range(label) + # time the kernel on the device, if a tracer wants that + timer = records_kernels(id) ? KernelTimer() : nothing try - launch_untraced(obj, args, ndrange, workgroupsize) + if timer === nothing + launch_untraced(obj, args, ndrange, workgroupsize) + else + # passed to `launch_kernel` in a scoped value rather than an argument, so that + # the launch path is inferred once for timed and other launches + with(() -> launch_untraced(obj, args, ndrange, workgroupsize), KERNEL_TIMER => timer) + end synchronize_launch(id, backend(obj)) finally profiling_range_end(id) + timer === nothing || timer.issued == 0 || trace_kernel(id, label, timer) end return nothing end @@ -146,11 +156,15 @@ function launch_kernel(obj::Kernel, launch, ndrange, _workgroupsize, iterspace, # launching through the `KI.Kernel` validates the sizes against the kernel's limits groups = size(blocks(iterspace)) items = size(workitems(iterspace)) + # timed around the launch alone, so that compilation isn't counted as device time; the + # timer comes from `launch_traced` + timer = start_kernel_timing(b) if launch isa NDLaunch call_kernel(kernel, ctx, args, groups, items) else call_kernel(kernel, ctx, args, prod(groups), prod(items)) end + stop_kernel_timing(timer, b) return nothing end diff --git a/src/profiler.jl b/src/profiler.jl index 0ebee12d0..e75d6f686 100644 --- a/src/profiler.jl +++ b/src/profiler.jl @@ -1,5 +1,4 @@ using Printf: @sprintf -using ScopedValues: ScopedValue, with ### # Built-in profiler: records the ranges of an expression, and summarizes them @@ -24,17 +23,29 @@ struct ProfileMarker thread::Int end +# a kernel's execution on the device, in host time +struct ProfileKernel + name::String + start::UInt64 + stop::UInt64 + device::String + task::Int # whose queue it ran on + host_timed::Bool # on a backend without timestamps, by synchronizing +end + struct ProfileTracer <: Tracer synchronize::Bool + device::Bool ranges::Vector{ProfileRange} markers::Vector{ProfileMarker} + kernels::Vector{Tuple{Symbol, Int, KernelTimer}} tasks::IdDict{Task, Int} open::Threads.Atomic{Int} # ranges started but not ended lock::ReentrantLock end -ProfileTracer(synchronize::Bool) = ProfileTracer( - synchronize, ProfileRange[], ProfileMarker[], IdDict{Task, Int}(), Threads.Atomic{Int}(0), - ReentrantLock() +ProfileTracer(synchronize::Bool, device::Bool = false) = ProfileTracer( + synchronize, device, ProfileRange[], ProfileMarker[], Tuple{Symbol, Int, KernelTimer}[], + IdDict{Task, Int}(), Threads.Atomic{Int}(0), ReentrantLock() ) # The profilers whose expression the current task is running, directly or in a task it @@ -49,6 +60,38 @@ function task_number(tracer::ProfileTracer) end synchronizes_launches(tracer::ProfileTracer) = tracer.synchronize && in_scope(tracer) +records_kernels(tracer::ProfileTracer) = tracer.device && in_scope(tracer) + +function trace_kernel(tracer::ProfileTracer, label, timer::KernelTimer) + task = task_number(tracer) + @lock tracer.lock push!(tracer.kernels, (label, task, timer)) + return nothing +end + +# Timestamps only measure intervals on a device, so the kernels are placed on the host's +# clock relative to the first kernel launched on each device, assuming it started when it +# was launched. A kernel can't start before it is launched, which bounds the error. +function resolve_kernels(kernels::Vector{Tuple{Symbol, Int, KernelTimer}}) + first_launched = Dict{Tuple{Any, Int}, KernelTimer}() + for (_, _, timer) in kernels + timer.host_timed && continue + key = (timer.backend, timer.device) + ref = Base.get(first_launched, key, nothing) + if ref === nothing || timer.issued < ref.issued + first_launched[key] = timer + end + end + return map(kernels) do (name, task, timer) + device = string(nameof(typeof(timer.backend)), " ", timer.device) + if timer.host_timed + return ProfileKernel(String(name), timer.start, timer.stop, device, task, true) + end + ref = first_launched[(timer.backend, timer.device)] + offset = KI.elapsed_time(timer.backend, ref.start, timer.start) + start = max(timer.issued, ref.issued + max(offset, 0)) + return ProfileKernel(String(name), start, start + max(elapsed(timer), 0), device, task, false) + end +end # like NVTXT, without domains of their own profile_name(label, domain) = domain === DEFAULT_DOMAIN ? String(label) : string(domain, ": ", label) @@ -77,21 +120,23 @@ end """ ProfileResults -The ranges and markers recorded by [`@profile`](@ref KernelAbstractions.@profile). Shown, -it summarizes the time spent per range name or, with `trace = true`, lists the ranges in -the order they started. `results.ranges` and `results.markers` hold the raw records, with -times in nanoseconds from `time_ns()`. +The ranges, markers and kernels recorded by [`@profile`](@ref KernelAbstractions.@profile). +Shown, it summarizes the time spent per name on the host and on the device or, with +`trace = true`, lists everything in the order it started. `results.ranges`, +`results.markers` and `results.kernels` hold the raw records, with times in nanoseconds +from `time_ns()`. """ struct ProfileResults start::UInt64 stop::UInt64 ranges::Vector{ProfileRange} markers::Vector{ProfileMarker} + kernels::Vector{ProfileKernel} trace::Bool end """ - KernelAbstractions.@profile [trace = false] [synchronize = true] expr + KernelAbstractions.@profile [trace = false] [device = true] [synchronize = false] expr Run `expr`, recording the ranges of [`@profiling_range`](@ref), the markers of [`profiling_mark`](@ref) and the kernel launches within it, and return a @@ -104,21 +149,31 @@ julia> KernelAbstractions.@profile for i in 1:10 add(backend)(A, B; ndrange = length(A)) end end -Profiled 6.04 ms, recording 30 ranges. +Profiled 3.04 ms, recording 30 ranges and 20 kernels. + +Host-side activity: + Time (%) Total time Calls Avg time Min time Max time Name + ──────── ────────── ───── ──────── ──────── ──────── ──── + 6.8 % 206 µs 10 20.6 µs 13.2 µs 77.3 µs step + 3.5 % 106 µs 10 10.6 µs 5.88 µs 47.1 µs mul2 + 2.7 % 81.5 µs 10 8.15 µs 6.43 µs 20.6 µs add +Device-side activity: Time (%) Total time Calls Avg time Min time Max time Name ──────── ────────── ───── ──────── ──────── ──────── ──── - 92.6 % 5.59 ms 10 559 µs 298 µs 2.9 ms step - 57.6 % 3.48 ms 10 348 µs 109 µs 2.48 ms mul2 - 37.6 % 2.27 ms 10 227 µs 179 µs 400 µs add + 51.3 % 1.56 ms 10 156 µs 155 µs 157 µs add + 45.8 % 1.39 ms 10 139 µs 137 µs 151 µs mul2 ``` -With `synchronize = true`, the default, kernel launches synchronize their backend before -their range ends, so that on GPU backends they measure the kernel's execution instead of -its launch. This serializes the host with the device, as `CUDA_LAUNCH_BLOCKING=1` does. +On the host, kernel ranges measure the launch. With `device = true`, the default, kernels +are also timed on the device, without synchronizing, on backends that implement +`KernelInterface.record_timestamp`. On other backends, a launch synchronizes its backend to +time the kernel from the host, which is marked with `*`. With `synchronize = true`, kernel +launches also synchronize before their host range ends. -With `trace = true`, the results list every range in the order it started instead, -indented by nesting on its task. +With `trace = true`, the results list every range and kernel in the order it started, +indented by nesting. Kernels are placed on the host's timeline relative to the first kernel +on their device, assuming that one started when it was launched. Only the task running `expr` and the tasks it spawns (with `KernelAbstractions.@spawn`, `Threads.@spawn` or `@async`) are recorded, so that other tasks, including other @@ -131,23 +186,25 @@ Other registered tracers, e.g. NVTX under Nsight Systems, record the ranges of a macro profile(args...) isempty(args) && throw(ArgumentError("KernelAbstractions.@profile needs an expression to profile")) expr = args[end] - trace, synchronize = false, true + options = Dict{Symbol, Any}(:trace => false, :device => true, :synchronize => false) for kw in args[1:(end - 1)] - if Meta.isexpr(kw, :(=)) && kw.args[1] === :trace - trace = kw.args[2] - elseif Meta.isexpr(kw, :(=)) && kw.args[1] === :synchronize - synchronize = kw.args[2] + if Meta.isexpr(kw, :(=)) && haskey(options, kw.args[1]) + options[kw.args[1]] = kw.args[2] else - throw(ArgumentError("KernelAbstractions.@profile: unexpected argument `$kw`; only `trace = ...` and `synchronize = ...` are accepted")) + throw(ArgumentError("KernelAbstractions.@profile: unexpected argument `$kw`; only `trace`, `device` and `synchronize` are accepted")) end end return quote - $profile(() -> $(esc(expr)); trace = $(esc(trace)), synchronize = $(esc(synchronize))) + $profile( + () -> $(esc(expr)); + trace = $(esc(options[:trace])), device = $(esc(options[:device])), + synchronize = $(esc(options[:synchronize])) + ) end end -function profile(f; trace::Bool = false, synchronize::Bool = true) - tracer = register_tracer!(ProfileTracer(synchronize)) +function profile(f; trace::Bool = false, device::Bool = true, synchronize::Bool = false) + tracer = register_tracer!(ProfileTracer(synchronize, device)) task_number(tracer) # the profiling task is task 1 start = time_ns() try @@ -158,7 +215,11 @@ function profile(f; trace::Bool = false, synchronize::Bool = true) stop = time_ns() open = tracer.open[] open > 0 && @warn "$(plural(open, "profiled range")) still open when `@profile` finished; wait for the tasks spawned within it, e.g. with `@sync`" - return @lock tracer.lock ProfileResults(start, stop, copy(tracer.ranges), copy(tracer.markers), trace) + ranges, markers, kernels = @lock tracer.lock copy(tracer.ranges), copy(tracer.markers), copy(tracer.kernels) + # waits for the kernels to complete + kernels = resolve_kernels(kernels) + stop = max(stop, maximum(k -> k.stop, kernels; init = stop)) + return ProfileResults(start, stop, ranges, markers, kernels, trace) end @@ -196,11 +257,12 @@ end function Base.show(io::IO, ::MIME"text/plain", results::ProfileResults) total = results.stop - results.start - nranges, nmarkers = length(results.ranges), length(results.markers) - print(io, "Profiled ", format_time(total), ", recording ", nranges, nranges == 1 ? " range" : " ranges") - nmarkers > 0 && print(io, " and ", nmarkers, nmarkers == 1 ? " marker" : " markers") - println(io, ".") - (nranges == 0 && nmarkers == 0) && return + nranges, nmarkers, nkernels = length(results.ranges), length(results.markers), length(results.kernels) + counts = [plural(nranges, "range")] + nmarkers > 0 && push!(counts, plural(nmarkers, "marker")) + nkernels > 0 && push!(counts, plural(nkernels, "kernel")) + println(io, "Profiled ", format_time(total), ", recording ", join(counts, ", ", " and "), ".") + (nranges == 0 && nmarkers == 0 && nkernels == 0) && return println(io) if results.trace show_trace(io, results) @@ -210,26 +272,45 @@ function Base.show(io::IO, ::MIME"text/plain", results::ProfileResults) return end +function summary_table(io::IO, records, total) + durations = Dict{String, Vector{UInt64}}() + for record in records + push!(get!(durations, record.name, UInt64[]), record.stop - record.start) + end + rows = sort!(collect(durations); by = kv -> sum(kv[2]), rev = true) + return print_table( + io, ["Time (%)", "Total time", "Calls", "Avg time", "Min time", "Max time", "Name"], + [ + [ + @sprintf("%.1f %%", 100 * sum(ds) / total), format_time(sum(ds)), string(length(ds)), + format_time(sum(ds) / length(ds)), format_time(minimum(ds)), format_time(maximum(ds)), + name, + ] for (name, ds) in rows + ] + ) +end + function show_summary(io::IO, results::ProfileResults, total) + sections = 0 if !isempty(results.ranges) - durations = Dict{String, Vector{UInt64}}() - for range in results.ranges - push!(get!(durations, range.name, UInt64[]), range.stop - range.start) - end - rows = sort!(collect(durations); by = kv -> sum(kv[2]), rev = true) - print_table( - io, ["Time (%)", "Total time", "Calls", "Avg time", "Min time", "Max time", "Name"], - [ - [ - @sprintf("%.1f %%", 100 * sum(ds) / total), format_time(sum(ds)), string(length(ds)), - format_time(sum(ds) / length(ds)), format_time(minimum(ds)), format_time(maximum(ds)), - name, - ] for (name, ds) in rows - ] - ) + println(io, "Host-side activity:") + summary_table(io, results.ranges, total) + sections += 1 + end + if !isempty(results.kernels) + sections > 0 && println(io) + println(io, "Device-side activity:") + kernels = [ + k.host_timed ? ProfileKernel(k.name * " *", k.start, k.stop, k.device, k.task, true) : k + for k in results.kernels + ] + summary_table(io, kernels, total) + any(k -> k.host_timed, kernels) && + println(io, "\n * timed on the host, as the backend doesn't support timestamps") + sections += 1 end if !isempty(results.markers) - isempty(results.ranges) || println(io) + sections > 0 && println(io) counts = Dict{String, Int}() for marker in results.markers counts[marker.name] = Base.get(counts, marker.name, 0) + 1 @@ -240,29 +321,33 @@ function show_summary(io::IO, results::ProfileResults, total) return end -location(event) = "task $(event.task) (thread $(event.thread))" +# host records nest on their task, kernels on the queue of their task on their device +location(event::Union{ProfileRange, ProfileMarker}) = "task $(event.task) (thread $(event.thread))" +location(kernel::ProfileKernel) = "$(kernel.device), task $(kernel.task)" function show_trace(io::IO, results::ProfileResults) - # the nesting depth of each range among the ranges on its task events = sort!( [ [(r.start, r) for r in results.ranges]; - [(m.time, m) for m in results.markers] + [(m.time, m) for m in results.markers]; + [(k.start, k) for k in results.kernels] ]; by = first ) - open = Dict{Int, Vector{UInt64}}() # stop times of the open ranges, per task + open = Dict{String, Vector{UInt64}}() # stop times of the open ranges, per task and queue rows = Vector{String}[] for (time, event) in events - stack = get!(open, event.task, UInt64[]) + stack = get!(open, location(event), UInt64[]) while !isempty(stack) && last(stack) <= time pop!(stack) end indent = " "^length(stack) - if event isa ProfileRange - push!(stack, event.stop) - push!(rows, [format_time(time - results.start), format_time(event.stop - event.start), location(event), indent * event.name]) + start = format_time(time - results.start) + if event isa ProfileMarker + push!(rows, [start, "", location(event), indent * "◆ " * event.name]) else - push!(rows, [format_time(time - results.start), "", location(event), indent * "◆ " * event.name]) + push!(stack, event.stop) + name = event isa ProfileKernel && event.host_timed ? event.name * " *" : event.name + push!(rows, [start, format_time(event.stop - event.start), location(event), indent * name]) end end print_table(io, ["Start", "Duration", "On", "Name"], rows) diff --git a/src/profiling.jl b/src/profiling.jl index 356651f6d..e3862d7fc 100644 --- a/src/profiling.jl +++ b/src/profiling.jl @@ -8,6 +8,8 @@ # none registered, an annotation costs one atomic load. ### +using ScopedValues: ScopedValue, with + """ Tracer @@ -21,10 +23,16 @@ Subtypes implement trace_range_end(tracer, id) trace_mark(tracer, label::Label, domain::Symbol) # optional synchronizes_launches(tracer)::Bool # optional, default `false` + records_kernels(tracer)::Bool # optional, default `false` + trace_kernel(tracer, label::Symbol, timer::KernelTimer) # if `records_kernels` If `synchronizes_launches` is `true`, kernel launches synchronize their backend before their range ends, so that the range measures the kernel's execution rather than its launch. +If `records_kernels` is `true`, kernel launches are timed on the device without +synchronizing, and passed to `trace_kernel` as a [`KernelTimer`](@ref), to be resolved +later with [`elapsed`](@ref). + A `Label` is a `Symbol` for labels that are fixed in the code: literals in [`@profiling_range`](@ref), kernel names and `@spawn` call sites. As there are only so many of those, tracers may cache what they derive from a `Symbol` label, e.g. a registered @@ -54,6 +62,8 @@ function trace_range_start end function trace_range_end end trace_mark(::Tracer, label, domain) = nothing synchronizes_launches(::Tracer) = false +records_kernels(::Tracer) = false +function trace_kernel end # copy-on-write, so that checking for tracers is a single atomic load mutable struct Tracers @@ -135,6 +145,82 @@ profiling_range_end(::Nothing) = nothing synchronizes_launches(range::ProfilingRange) = any(synchronizes_launches, range.tracers) synchronizes_launches(::Nothing) = false +records_kernels(range::ProfilingRange) = any(records_kernels, range.tracers) +records_kernels(::Nothing) = false +function trace_kernel(range::ProfilingRange, label, timer) + for tracer in range.tracers + records_kernels(tracer) && trace_kernel(tracer, label, timer) + end + return nothing +end + +""" + KernelTimer + +The device time of a kernel launch, for tracers that record kernels. It holds the +backend's timestamps (see `KernelInterface.record_timestamp`) around the launch, which are +resolved by [`elapsed`](@ref). On backends without timestamps, the launch synchronizes, and +the timer holds host times instead. + +- `backend`, `device`: where the kernel ran +- `issued`: the host time (`time_ns()`) at which the kernel was launched +- `start`, `stop`: the timestamps, or host times if `host_timed` +""" +mutable struct KernelTimer + backend::Any + device::Int + issued::UInt64 + start::Any + stop::Any + host_timed::Bool + KernelTimer() = new(nothing, 0, 0, nothing, nothing, false) +end + +# the timer of the launch the current task is tracing, if any +const KERNEL_TIMER = ScopedValue{Union{Nothing, KernelTimer}}(nothing) + +# Called around every kernel launch, out of line to keep the code of every kernel's launch +# small: with tracing off, all that is compiled for a kernel is these two calls. +@noinline function start_kernel_timing(backend) + profiling_active() || return nothing + timer = KERNEL_TIMER[] + timer === nothing || start_timing!(timer, backend) + return timer +end +@noinline function stop_kernel_timing(timer, backend) + timer === nothing || stop_timing!(timer, backend) + return nothing +end + +@noinline function start_timing!(timer::KernelTimer, backend) + timer.backend = backend + timer.device = KI.device(backend) + timer.issued = time_ns() + timer.start = KI.record_timestamp(backend) + if timer.start === nothing + timer.host_timed = true + timer.start = timer.issued + end + return +end + +@noinline function stop_timing!(timer::KernelTimer, backend) + if timer.host_timed + KI.synchronize(backend) + timer.stop = time_ns() + else + timer.stop = KI.record_timestamp(backend) + end + return +end + +""" + elapsed(timer::KernelTimer)::Int64 + +The device time of the kernel in nanoseconds, waiting for it to complete. +""" +elapsed(timer::KernelTimer) = timer.host_timed ? Int64(timer.stop - timer.start) : + KI.elapsed_time(timer.backend, timer.start, timer.stop) """ profiling_mark(label; domain = :KernelAbstractions) diff --git a/test/runtests.jl b/test/runtests.jl index 5d843d9e6..d0c9a37d7 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -555,15 +555,30 @@ end @test length(results.markers) == 3 @test all(r -> results.start <= r.start <= r.stop <= results.stop, results.ranges) + # on a backend without timestamps, kernels are timed on the host + @test count(k -> k.name == "profiling_fill!", results.kernels) == 6 + @test all(k -> k.host_timed && k.device == "POCLBackend 1", results.kernels) + @test all(k -> results.start <= k.start <= k.stop <= results.stop, results.kernels) + summary = sprint(show, MIME"text/plain"(), results) @test startswith(summary, "Profiled ") - @test occursin("recording 9 ranges and 3 markers.", summary) + @test occursin("recording 9 ranges, 3 markers and 6 kernels.", summary) lines = split(summary, '\n') - @test occursin("Total time", lines[3]) + host = findfirst(==("Host-side activity:"), lines) + device = findfirst(==("Device-side activity:"), lines) + @test host !== nothing && device !== nothing && host < device + @test occursin("Total time", lines[host + 1]) # sorted by total time - @test endswith(lines[5], "Demo: step") && endswith(lines[6], "profiling_fill!") + @test endswith(lines[host + 3], "Demo: step") && endswith(lines[host + 4], "profiling_fill!") + @test endswith(lines[device + 3], "profiling_fill! *") + @test any(l -> occursin("timed on the host", l), lines) @test any(l -> occursin(r"^ +3 half$", l), lines) + # without device timing, there are only host ranges + results = KernelAbstractions.@profile device = false kfill!(CPU())(A, 1.0f0; ndrange = length(A)) + @test isempty(results.kernels) && length(results.ranges) == 1 + @test KernelAbstractions.KI.record_timestamp(NewBackend()) === nothing + trace = sprint( show, MIME"text/plain"(), KernelAbstractions.@profile trace = true begin @profiling_range "outer" begin @@ -586,6 +601,11 @@ end KernelAbstractions.synchronizes_launches(tracer) end @test !KernelAbstractions.synchronizes_launches(KernelAbstractions.ProfileTracer(false)) + tracer = KernelAbstractions.ProfileTracer(false, true) + @test !KernelAbstractions.records_kernels(tracer) + @test KernelAbstractions.with(KernelAbstractions.PROFILERS => [tracer]) do + KernelAbstractions.records_kernels(tracer) + end @test !KernelAbstractions.synchronizes_launches(Testsuite.RecordingTracer()) results = KernelAbstractions.@profile synchronize = false kfill!(CPU())(A, 1.0f0; ndrange = length(A)) @test only(results.ranges).name == "profiling_fill!" @@ -612,6 +632,8 @@ end task = only(r.task for r in results.ranges if r.name == "task $i") @test count(r -> r.name == "profiling_fill!" && r.task == task, results.ranges) == 1 end + # as is each kernel, on its task's queue + @test sort([k.task for k in results.kernels]) == 2:4 # `@spawn` ranges are named after the call site, and belong to the spawned task spawns = filter(r -> startswith(r.name, "@spawn runtests.jl:"), results.ranges) @test sort([r.task for r in spawns]) == 2:4 @@ -621,8 +643,9 @@ end end named = KernelAbstractions.@profile wait(KernelAbstractions.@spawn CPU() name = "named" nothing) @test only(named.ranges).name == "named" - trace = sprint(show, MIME"text/plain"(), KernelAbstractions.ProfileResults(results.start, results.stop, results.ranges, results.markers, true)) + trace = sprint(show, MIME"text/plain"(), KernelAbstractions.ProfileResults(results.start, results.stop, results.ranges, results.markers, results.kernels, true)) @test occursin("task 1 (thread ", trace) + @test occursin("POCLBackend 1, task 2", trace) # other tasks aren't stop = Threads.Atomic{Bool}(false)