Add count of lock conflicts to @time etc. Add @lock_conflicts (#52883)

Author: IanButterworth

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
 ----------------

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
 

base/exports.jl

@@ -1036,6 +1036,7 @@ export
     @elapsed,
     @allocated,
     @allocations,
+    @lock_conflicts,
 
     # tasks
     @sync,

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

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,21 +540,34 @@ 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)
         local compile_elapsedtimes = cumulative_compile_time_ns()
         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

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

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