update other time macros and add @lock_conflicts

Author: IanButterworth

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

base/exports.jl

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

base/timing.jl

@@ -195,11 +195,11 @@ function time_print(io::IO, elapsedtime, bytes=0, gctime=0, allocs=0, lock_confl
     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")
@@ -231,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.
 
@@ -252,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);
 
@@ -373,18 +377,22 @@ end
 macro timev(msg, 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)
         local _msg = $(esc(msg))
-        timev_print(elapsedtime, diff, compile_elapsedtimes; msg=_msg)
+        timev_print(elapsedtime, diff, lock_conflicts, compile_elapsedtimes; msg=_msg)
         val
     end
 end
@@ -478,6 +486,41 @@ 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 evalution, 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
 
@@ -513,15 +556,23 @@ julia> stats.gcstats.total_time
 
 !!! compat "Julia 1.5"
     The return type of this macro was changed from `Tuple` to `NamedTuple` in Julia 1.5.
+
+!!! compat "Julia 1.11"
+    The field `lock_conflicts` was added to the returned NamedTuple 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()
-        local val = $(esc(ex))
-        elapsedtime = time_ns() - elapsedtime
+        local val = @__tryfinally($(esc(ex)),
+            (elapsedtime = time_ns() - elapsedtime;
+            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)
+        (value=val, time=elapsedtime/1e9, bytes=diff.allocd, gctime=diff.total_time/1e9, gcstats=diff, lock_conflicts=lock_conflicts)
     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

@@ -1391,6 +1391,16 @@ end
     @test (@allocations "a") == 0
     @test (@allocations "a" * "b") == 0 # constant propagation
     @test (@allocations "a" * Base.inferencebarrier("b")) == 1
+
+    lc = @lock_conflicts begin
+        l = ReentrantLock()
+        Threads.@threads for i in 1:Threads.nthreads()
+            lock(l) do
+                sleep(0.5)
+            end
+        end
+    end
+    @test lc = Threads.nthreads() - 1
 end
 
 @testset "in_finalizer" begin