Skip to content

Commit

Permalink
add lock conflicts to @time etc. add @lock_conflicts
Browse files Browse the repository at this point in the history
  • Loading branch information
IanButterworth committed Jan 21, 2024
1 parent 9c78420 commit d7ebd53
Show file tree
Hide file tree
Showing 7 changed files with 93 additions and 11 deletions.
2 changes: 2 additions & 0 deletions NEWS.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
----------------
Expand Down
7 changes: 7 additions & 0 deletions base/atomics.jl
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
1 change: 1 addition & 0 deletions base/exports.jl
Original file line number Diff line number Diff line change
Expand Up @@ -1036,6 +1036,7 @@ export
@elapsed,
@allocated,
@allocations,
@lock_conflicts,

# tasks
@sync,
Expand Down
1 change: 1 addition & 0 deletions base/lock.jl
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
80 changes: 69 additions & 11 deletions base/timing.jl
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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, ", ")
Expand All @@ -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")
Expand Down Expand Up @@ -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.
Expand All @@ -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);
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -493,21 +538,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
1 change: 1 addition & 0 deletions doc/src/base/base.md
Original file line number Diff line number Diff line change
Expand Up @@ -352,6 +352,7 @@ Base.@timed
Base.@elapsed
Base.@allocated
Base.@allocations
Base.@lock_conflicts
Base.EnvDict
Base.ENV
Base.Sys.STDLIB
Expand Down
12 changes: 12 additions & 0 deletions test/misc.jl
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down

0 comments on commit d7ebd53

Please sign in to comment.