diff --git a/base/atomics.jl b/base/atomics.jl index c35f8dd01b32b4..dde981b8c0e6af 100644 --- a/base/atomics.jl +++ b/base/atomics.jl @@ -80,7 +80,12 @@ end Atomic() = Atomic{Int}() -LOCK_CONFLICT_COUNT = Threads.Atomic{Int}(0); +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/lock.jl b/base/lock.jl index a1fa400aec54d4..b593ebd10d2609 100644 --- a/base/lock.jl +++ b/base/lock.jl @@ -134,9 +134,6 @@ end return false end -LOCK_PROFILING::Bool = false -inc_lock_conflict_count() = Threads.atomic_add!(Threads.LOCK_CONFLICT_COUNT, 1) - """ lock(lock) @@ -148,7 +145,7 @@ Each `lock` must be matched by an [`unlock`](@ref). """ @inline function lock(rl::ReentrantLock) trylock(rl) || (@noinline function slowlock(rl::ReentrantLock) - LOCK_PROFILING && inc_lock_conflict_count() + 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 472efcd94cb081..9747395e4b316b 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_conflict, " lock conflict$plural") + end if compile_time > 0 if bytes != 0 || allocs != 0 || gctime > 0 print(io, ", ") @@ -282,6 +287,8 @@ end macro time(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) @@ -289,11 +296,13 @@ macro time(msg, 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) local _msg = $(esc(msg)) - time_print(stdout, elapsedtime, diff.allocd, diff.total_time, gc_alloc_count(diff), first(compile_elapsedtimes), last(compile_elapsedtimes), true; msg=_msg) + time_print(stdout, elapsedtime, diff.allocd, diff.total_time, gc_alloc_count(diff), first(compile_elapsedtimes), last(compile_elapsedtimes), lock_conflicts, true; msg=_msg) val end end diff --git a/stdlib/Profile/src/Profile.jl b/stdlib/Profile/src/Profile.jl index bf61f80ef9846d..aad97be6833091 100644 --- a/stdlib/Profile/src/Profile.jl +++ b/stdlib/Profile/src/Profile.jl @@ -10,7 +10,6 @@ Profiling support. - `Profile.print()` to print the report. - `Profile.clear()` to clear the buffer. - Send a $(Sys.isbsd() ? "SIGINFO (ctrl-t)" : "SIGUSR1") signal to the process to automatically trigger a profile and print. -- `@count_lock_conflicts foo()` to count how many times a task had to wait to acquire a lock. ## Memory profiling - `Profile.Allocs.@profile [sample_rate=0.1] foo()` to sample allocations within a specific call. A sample rate of 1.0 will record everything; 0.0 will record nothing. @@ -45,7 +44,7 @@ const nmeta = 4 # number of metadata fields per block (threadid, taskid, cpu_cyc # deprecated functions: use `getdict` instead lookup(ip::UInt) = lookup(convert(Ptr{Cvoid}, ip)) -export @profile, @count_lock_conflicts +export @profile """ @profile @@ -64,26 +63,6 @@ macro profile(ex) end end - -""" - @count_lock_conflicts - -`count_lock_conflicts ` runs your expression while monitoring how many times a task had to wait -to acquire a lock. -""" -macro count_lock_conflicts(ex) - return quote - Base.LOCK_PROFILING = true - Threads.LOCK_CONFLICT_COUNT[] = 0 - try - $(esc(ex)) - finally - Base.LOCK_PROFILING = false - end - println("$(Threads.LOCK_CONFLICT_COUNT[]) lock conflicts") - end -end - # An internal function called to show the report after an information request (SIGINFO or SIGUSR1). function _peek_report() iob = IOBuffer()