add excessive scheduling time to time macro etc.

Author: IanButterworth

base/Base.jl

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

base/task.jl

@@ -1098,7 +1098,20 @@ end
 
 function try_yieldto(undo)
     try
+        # when timing time spent in the scheduler we time the time spent in the task
+        # then subtract the elapsed time in `@timed` from the total time to get the scheduler time
+        t, ts = isassigned(Workqueue_sched_times) ? (time_ns(), Workqueue_sched_times[]) : (nothing, nothing)
         ccall(:jl_switch, Cvoid, ())
+        if ts !== nothing
+            t = time_ns() - t
+            tid = Threads.threadid()
+            if tid <= length(ts)
+                ts[tid] += t
+            else
+                # this might be redundant? doesn't seem that try_yieldto is ever called from a thread other than 1?
+                println("WARNING: Workqueue_sched_times is too short. tid: $tid, length: $(length(ts))")
+            end
+        end
     catch
         undo(ccall(:jl_get_next_task, Ref{Task}, ()))
         rethrow()

base/timing.jl

@@ -196,17 +196,18 @@ 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)
+    wall_time_sched_perc = wall_time_sched / (elapsedtime / 1e9)
     str = sprint() do io
         if msg isa String
             print(io, msg, ": ")
         else
             print(io, length(timestr) < 10 ? (" "^(10 - length(timestr))) : "")
         end
         print(io, timestr, " seconds")
-        parens = bytes != 0 || allocs != 0 || gctime > 0 || lock_conflicts > 0 || compile_time > 0
+        parens = bytes != 0 || allocs != 0 || gctime > 0 || wall_time_sched_perc > 0.1 || lock_conflicts > 0 || compile_time > 0
         parens && print(io, " (")
         if bytes != 0 || allocs != 0
             allocs, ma = prettyprint_getunits(allocs, length(_cnt_units), Int64(1000))
@@ -223,15 +224,21 @@ 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
-        if lock_conflicts > 0
+        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 || lock_conflicts > 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")
@@ -346,7 +353,7 @@ macro time(msg, ex)
         local ret = @timed $(esc(ex))
         local _msg = $(esc(msg))
         local _msg_str = _msg === nothing ? _msg : string(_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_str)
+        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_str)
         ret.value
     end
 end
@@ -600,29 +607,37 @@ julia> stats.recompile_time
 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;
-            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,
-            lock_conflicts=lock_conflicts,
-            compile_time=compile_elapsedtimes[1]/1e9,
-            recompile_time=compile_elapsedtimes[2]/1e9
-        )
+        ScopedValues.@with Workqueue_sched_times => zeros(UInt, Threads.maxthreadid()) begin
+            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;
+                lock_conflicts = Threads.LOCK_CONFLICT_COUNT[] - lock_conflicts;
+                Threads.lock_profiling(false))
+            )
+            local diff = GC_Diff(gc_num(), stats)
+            # filter out zeros which can only happen if nothing was scheduled
+            local sched_times = Int.(filter(>(0), Workqueue_sched_times[]))
+            local wall_time_sched = isempty(sched_times) ? 0 : sum(Int(elapsedtime) .- sched_times) / length(sched_times)
+
+            (
+                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,
+                wall_time_sched=wall_time_sched/1e9
+            )
+        end
     end
 end