add excessive scheduling time to time macro etc.

Author: IanButterworth

base/Base.jl

@@ -423,6 +423,9 @@ include("weakkeydict.jl")
 include("scopedvalues.jl")
 using .ScopedValues
 
+# used by task.jl
+const Workqueue_sched_times = ScopedValue{Vector{UInt}}()
+
 # metaprogramming
 include("meta.jl")
 

base/task.jl

@@ -931,7 +931,8 @@ function workqueue_for(tid::Int)
         if length(qs) < tid
             nt = Threads.maxthreadid()
             @assert tid <= nt
-            global Workqueues = qs = copyto!(typeof(qs)(undef, length(qs) + nt - 1), qs)
+            new_length = length(qs) + nt - 1
+            global Workqueues = qs = copyto!(typeof(qs)(undef, new_length), qs)
         end
         if !isassigned(qs, tid)
             @inbounds qs[tid] = StickyWorkqueue()
@@ -1173,8 +1174,17 @@ end
 
 function wait()
     GC.safepoint()
-    W = workqueue_for(Threads.threadid())
+    tid = Threads.threadid()
+    W = workqueue_for(tid)
+    t = time_ns()
     poptask(W)
+    t = time_ns() - t
+    if isassigned(Workqueue_sched_times)
+        ts = Workqueue_sched_times[]
+        if tid <= length(ts) # TODO: Grow Workqueue_sched_times if needed, but needs to be threadsafe
+            ts[tid] += t
+        end
+    end
     result = try_yieldto(ensure_rescheduled)
     process_events()
     # return when we come out of the queue

base/timing.jl

@@ -169,8 +169,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, lock_conflicts=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, wall_time_sched=0,
+                    newline=false; msg::Union{String,Nothing}=nothing)
     timestr = Ryu.writefixed(Float64(elapsedtime/1e9), 6)
     str = sprint() do io
         if msg isa String
@@ -196,12 +196,22 @@ function time_print(io::IO, elapsedtime, bytes=0, gctime=0, allocs=0, lock_confl
             end
             print(io, Ryu.writefixed(Float64(100*gctime/elapsedtime), 2), "% gc time")
         end
+        wall_time_sched_perc = wall_time_sched / (elapsedtime / 1e9)
+        if wall_time_sched_perc > 0.1
+            if bytes != 0 || allocs != 0 || gctime > 0
+                print(io, ", ")
+            end
+            print(io, Ryu.writefixed(Float64(100*wall_time_sched_perc), 2), "% wall time scheduling")
+        end
         if lock_conflicts > 0
+            if bytes != 0 || allocs != 0 || gctime > 0 || wall_time_sched_perc > 0.1
+                print(io, ", ")
+            end
             plural = lock_conflicts == 1 ? "" : "s"
             print(io, ", ", lock_conflicts, " lock conflict$plural")
         end
         if compile_time > 0
-            if bytes != 0 || allocs != 0 || gctime > 0
+            if bytes != 0 || allocs != 0 || gctime > 0 || wall_time_sched_perc > 0.1 || lock_conflicts > 0
                 print(io, ", ")
             end
             print(io, Ryu.writefixed(Float64(100*compile_time/elapsedtime), 2), "% compilation time")
@@ -315,7 +325,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.lock_conflicts, 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, ret.wall_time_sched, true; msg=_msg)
         ret.value
     end
 end
@@ -574,13 +584,19 @@ macro timed(ex)
         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;
-            lock_conflicts = Threads.LOCK_CONFLICT_COUNT[] - lock_conflicts;
-            Threads.lock_profiling(false))
-        )
+        local wall_time_sched = 0.0
+        @with Workqueue_sched_times => zeros(UInt, Threads.maxthreadid()) begin
+            sched_ts = copy(Base.Workqueue_sched_times[])
+            local val = @__tryfinally($(esc(ex)),
+                (elapsedtime = time_ns() - elapsedtime;
+                cumulative_compile_timing(false);
+                compile_elapsedtimes = cumulative_compile_time_ns() .- compile_elapsedtimes;
+                lock_conflicts = Threads.LOCK_CONFLICT_COUNT[] - lock_conflicts;
+                Threads.lock_profiling(false))
+            )
+            wall_time_sched = sum(Base.Workqueue_sched_times[] .- sched_ts) / (Threads.nthreads(:interactive) + Threads.nthreads(:default))
+        end
+
         local diff = GC_Diff(gc_num(), stats)
         (
             value=val,
@@ -590,7 +606,8 @@ macro timed(ex)
             gcstats=diff,
             lock_conflicts=lock_conflicts,
             compile_time=compile_elapsedtimes[1]/1e9,
-            recompile_time=compile_elapsedtimes[2]/1e9
+            recompile_time=compile_elapsedtimes[2]/1e9,
+            wall_time_sched=wall_time_sched/1e9
         )
     end
 end