move to @time

Author: IanButterworth

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

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

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,18 +287,22 @@ 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)
         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))
-        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

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 <expression>` 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()