From 12c5d2dff8d0c34ac4c8a8b10c9a6f467d8f9d46 Mon Sep 17 00:00:00 2001 From: Ian Butterworth Date: Fri, 2 Feb 2024 18:48:54 -0500 Subject: [PATCH] Add count of lock conflicts to `@time` etc. Add `@lock_conflicts` (#52883) --- NEWS.md | 2 ++ base/atomics.jl | 7 ++++ base/exports.jl | 1 + base/lock.jl | 1 + base/timing.jl | 82 ++++++++++++++++++++++++++++++++++++++------ doc/src/base/base.md | 1 + test/misc.jl | 23 ++++++++++--- 7 files changed, 102 insertions(+), 15 deletions(-) diff --git a/NEWS.md b/NEWS.md index c6b5469143638..6e7384e730efb 100644 --- a/NEWS.md +++ b/NEWS.md @@ -30,6 +30,8 @@ New language features a `Manifest-v1.11.toml` would be used by v1.11 and `Manifest.toml` by every other julia version. This makes managing environments for multiple julia versions at the same time easier ([#43845]). +* `@time` now reports a count of any lock conflicts where a `ReentrantLock` had to wait, plus a new macro + `@lock_conflicts` which returns that count ([#52883]). Language changes ---------------- diff --git a/base/atomics.jl b/base/atomics.jl index 7312206c19896..dde981b8c0e6a 100644 --- a/base/atomics.jl +++ b/base/atomics.jl @@ -80,6 +80,13 @@ end Atomic() = Atomic{Int}() +const LOCK_PROFILING = Atomic{Int}(0) +lock_profiling(state::Bool) = state ? atomic_add!(LOCK_PROFILING, 1) : atomic_sub!(LOCK_PROFILING, 1) +lock_profiling() = LOCK_PROFILING[] > 0 + +const LOCK_CONFLICT_COUNT = Atomic{Int}(0); +inc_lock_conflict_count() = atomic_add!(LOCK_CONFLICT_COUNT, 1) + """ Threads.atomic_cas!(x::Atomic{T}, cmp::T, newval::T) where T diff --git a/base/exports.jl b/base/exports.jl index 92525b85c7635..a9a753d0fda52 100644 --- a/base/exports.jl +++ b/base/exports.jl @@ -1036,6 +1036,7 @@ export @elapsed, @allocated, @allocations, + @lock_conflicts, # tasks @sync, diff --git a/base/lock.jl b/base/lock.jl index 73722050699ee..eb76a3b30e6a4 100644 --- a/base/lock.jl +++ b/base/lock.jl @@ -145,6 +145,7 @@ Each `lock` must be matched by an [`unlock`](@ref). """ @inline function lock(rl::ReentrantLock) trylock(rl) || (@noinline function slowlock(rl::ReentrantLock) + Threads.lock_profiling() && Threads.inc_lock_conflict_count() c = rl.cond_wait lock(c.lock) try diff --git a/base/timing.jl b/base/timing.jl index 1b93f97c122c1..382a16e61b1e4 100644 --- a/base/timing.jl +++ b/base/timing.jl @@ -146,7 +146,8 @@ function format_bytes(bytes; binary=true) # also used by InteractiveUtils end end -function time_print(io::IO, elapsedtime, bytes=0, gctime=0, allocs=0, compile_time=0, recompile_time=0, newline=false; msg::Union{String,Nothing}=nothing) +function time_print(io::IO, elapsedtime, bytes=0, gctime=0, allocs=0, lock_conflicts=0, compile_time=0, recompile_time=0, newline=false; + msg::Union{String,Nothing}=nothing) timestr = Ryu.writefixed(Float64(elapsedtime/1e9), 6) str = sprint() do io if msg isa String @@ -172,6 +173,10 @@ function time_print(io::IO, elapsedtime, bytes=0, gctime=0, allocs=0, compile_ti end print(io, Ryu.writefixed(Float64(100*gctime/elapsedtime), 2), "% gc time") end + if lock_conflicts > 0 + plural = lock_conflicts == 1 ? "" : "s" + print(io, ", ", lock_conflicts, " lock conflict$plural") + end if compile_time > 0 if bytes != 0 || allocs != 0 || gctime > 0 print(io, ", ") @@ -190,11 +195,11 @@ function time_print(io::IO, elapsedtime, bytes=0, gctime=0, allocs=0, compile_ti nothing end -function timev_print(elapsedtime, diff::GC_Diff, compile_times; msg::Union{String,Nothing}=nothing) +function timev_print(elapsedtime, diff::GC_Diff, lock_conflicts, compile_times; msg::Union{String,Nothing}=nothing) allocs = gc_alloc_count(diff) compile_time = first(compile_times) recompile_time = last(compile_times) - time_print(stdout, elapsedtime, diff.allocd, diff.total_time, allocs, compile_time, recompile_time, true; msg) + time_print(stdout, elapsedtime, diff.allocd, diff.total_time, allocs, lock_conflicts, compile_time, recompile_time, true; msg) padded_nonzero_print(elapsedtime, "elapsed time (ns)") padded_nonzero_print(diff.total_time, "gc time (ns)") padded_nonzero_print(diff.allocd, "bytes allocated") @@ -226,7 +231,8 @@ end A macro to execute an expression, printing the time it took to execute, the number of allocations, and the total number of bytes its execution caused to be allocated, before returning the value of the expression. Any time spent garbage collecting (gc), compiling -new code, or recompiling invalidated code is shown as a percentage. +new code, or recompiling invalidated code is shown as a percentage. Any lock conflicts +where a [`ReentrantLock`](@ref) had to wait are shown as a count. Optionally provide a description string to print before the time report. @@ -247,6 +253,9 @@ See also [`@showtime`](@ref), [`@timev`](@ref), [`@timed`](@ref), [`@elapsed`](@ Recompilation time being shown separately from compilation time was introduced in Julia 1.8 +!!! compat "Julia 1.11" + The reporting of any lock conflicts was added in Julia 1.11. + ```julia-repl julia> x = rand(10,10); @@ -283,7 +292,7 @@ macro time(msg, ex) quote local ret = @timed $(esc(ex)) local _msg = $(esc(msg)) - time_print(stdout, ret.time*1e9, ret.gcstats.allocd, ret.gcstats.total_time, gc_alloc_count(ret.gcstats), ret.compile_time*1e9, ret.recompile_time*1e9, true; msg=_msg) + time_print(stdout, ret.time*1e9, ret.gcstats.allocd, ret.gcstats.total_time, gc_alloc_count(ret.gcstats), ret.lock_conflicts, ret.compile_time*1e9, ret.recompile_time*1e9, true; msg=_msg) ret.value end end @@ -355,7 +364,7 @@ macro timev(msg, ex) quote local ret = @timed $(esc(ex)) local _msg = $(esc(msg)) - timev_print(ret.time*1e9, ret.gcstats, (ret.compile_time*1e9, ret.recompile_time*1e9); msg=_msg) + timev_print(ret.time*1e9, ret.gcstats, ret.lock_conflicts, (ret.compile_time*1e9, ret.recompile_time*1e9); msg=_msg) ret.value end end @@ -449,19 +458,57 @@ macro allocations(ex) end end +""" + @lock_conflicts + +A macro to evaluate an expression, discard the resulting value, and instead return the +total number of lock conflicts during evaluation, where a lock attempt on a [`ReentrantLock`](@ref) +resulted in a wait because the lock was already held. + +See also [`@time`](@ref), [`@timev`](@ref) and [`@timed`](@ref). + +```julia-repl +julia> @lock_conflicts begin + l = ReentrantLock() + Threads.@threads for i in 1:Threads.nthreads() + lock(l) do + sleep(1) + end + end +end +5 +``` + +!!! compat "Julia 1.11" + This macro was added in Julia 1.11. +""" +macro lock_conflicts(ex) + quote + Threads.lock_profiling(true) + local lock_conflicts = Threads.LOCK_CONFLICT_COUNT[] + try + $(esc(ex)) + finally + Threads.lock_profiling(false) + end + Threads.LOCK_CONFLICT_COUNT[] - lock_conflicts + end +end + """ @timed A macro to execute an expression, and return the value of the expression, elapsed time in seconds, total bytes allocated, garbage collection time, an object with various memory allocation -counters, compilation time in seconds, and recompilation time in seconds. +counters, compilation time in seconds, and recompilation time in seconds. Any lock conflicts +where a [`ReentrantLock`](@ref) had to wait are shown as a count. In some cases the system will look inside the `@timed` expression and compile some of the called code before execution of the top-level expression begins. When that happens, some compilation time will not be counted. To include this time you can run `@timed @eval ...`. See also [`@time`](@ref), [`@timev`](@ref), [`@elapsed`](@ref), -[`@allocated`](@ref), and [`@allocations`](@ref). +[`@allocated`](@ref), [`@allocations`](@ref), and [`@lock_conflicts`](@ref). ```julia-repl julia> stats = @timed rand(10^6); @@ -493,11 +540,13 @@ julia> stats.recompile_time The return type of this macro was changed from `Tuple` to `NamedTuple` in Julia 1.5. !!! compat "Julia 1.11" - The `compile_time` and `recompile_time` fields were added in Julia 1.11. + The `lock_conflicts`, `compile_time`, and `recompile_time` fields were added in Julia 1.11. """ macro timed(ex) quote Experimental.@force_compile + Threads.lock_profiling(true) + local lock_conflicts = Threads.LOCK_CONFLICT_COUNT[] local stats = gc_num() local elapsedtime = time_ns() cumulative_compile_timing(true) @@ -505,9 +554,20 @@ macro timed(ex) local val = @__tryfinally($(esc(ex)), (elapsedtime = time_ns() - elapsedtime; cumulative_compile_timing(false); - compile_elapsedtimes = cumulative_compile_time_ns() .- compile_elapsedtimes) + compile_elapsedtimes = cumulative_compile_time_ns() .- compile_elapsedtimes; + lock_conflicts = Threads.LOCK_CONFLICT_COUNT[] - lock_conflicts; + Threads.lock_profiling(false)) ) local diff = GC_Diff(gc_num(), stats) - (value=val, time=elapsedtime/1e9, bytes=diff.allocd, gctime=diff.total_time/1e9, gcstats=diff, compile_time=compile_elapsedtimes[1]/1e9, recompile_time=compile_elapsedtimes[2]/1e9) + ( + value=val, + time=elapsedtime/1e9, + bytes=diff.allocd, + gctime=diff.total_time/1e9, + gcstats=diff, + lock_conflicts=lock_conflicts, + compile_time=compile_elapsedtimes[1]/1e9, + recompile_time=compile_elapsedtimes[2]/1e9 + ) end end diff --git a/doc/src/base/base.md b/doc/src/base/base.md index ee9cede4e6455..0d1692b0ed581 100644 --- a/doc/src/base/base.md +++ b/doc/src/base/base.md @@ -352,6 +352,7 @@ Base.@timed Base.@elapsed Base.@allocated Base.@allocations +Base.@lock_conflicts Base.EnvDict Base.ENV Base.Sys.STDLIB diff --git a/test/misc.jl b/test/misc.jl index 11410a497a4f5..e0961c538921a 100644 --- a/test/misc.jl +++ b/test/misc.jl @@ -1392,10 +1392,25 @@ end @testset "Base/timing.jl" begin @test Base.jit_total_bytes() >= 0 - # sanity check `@allocations` returns what we expect in some very simple cases - @test (@allocations "a") == 0 - @test (@allocations "a" * "b") == 0 # constant propagation - @test (@allocations "a" * Base.inferencebarrier("b")) == 1 + # sanity check `@allocations` returns what we expect in some very simple cases. + # These are inside functions because `@allocations` uses `Experimental.@force_compile` + # so can be affected by other code in the same scope. + @test (() -> @allocations "a")() == 0 + @test (() -> @allocations "a" * "b")() == 0 # constant propagation + @test (() -> @allocations "a" * Base.inferencebarrier("b"))() == 1 + + _lock_conflicts, _nthreads = eval(Meta.parse(read(`$(Base.julia_cmd()) -tauto -E ' + _lock_conflicts = @lock_conflicts begin + l = ReentrantLock() + Threads.@threads for i in 1:Threads.nthreads() + lock(l) do + sleep(1) + end + end + end + _lock_conflicts,Threads.nthreads() + '`, String))) + @test _lock_conflicts > 0 skip=(_nthreads < 2) # can only test if the worker can multithread end #TODO: merge with `@testset "Base/timing.jl"` once https://github.com/JuliaLang/julia/issues/52948 is resolved