diff --git a/NEWS.md b/NEWS.md index ed065939ad067d..54318569a76a1c 100644 --- a/NEWS.md +++ b/NEWS.md @@ -21,6 +21,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 lock 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 7312206c198968..dde981b8c0e6af 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 92525b85c76353..a9a753d0fda52b 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 73722050699ee1..eb76a3b30e6a4c 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 e980cb9a05e934..29978988d49ceb 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 lock 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,55 @@ 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 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 + Experimental.@force_compile + Threads.lock_profiling(true) + local lock_conflicts = Threads.LOCK_CONFLICT_COUNT[] + $(esc(ex)) + Threads.lock_profiling(false) + 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 lock 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 +538,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 +552,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 7172474b40b397..bd942e04bdf257 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 6f6dd3d806a7ba..6273265ff0a2e1 100644 --- a/test/misc.jl +++ b/test/misc.jl @@ -1394,6 +1394,18 @@ end @test (@allocations "a") == 0 @test (@allocations "a" * "b") == 0 # constant propagation @test (@allocations "a" * Base.inferencebarrier("b")) == 1 + + lock_conflicts = parse(Int, read(`$(Base.julia_cmd()) -tauto -E ' + @lock_conflicts begin + l = ReentrantLock() + Threads.@threads for i in 1:Threads.nthreads() + lock(l) do + sleep(rand()) + end + end + end + '`, String)) + @test lock_conflicts > 0 end @testset "in_finalizer" begin