Skip to content

Commit

Permalink
add excessive scheduling time to time macro etc.
Browse files Browse the repository at this point in the history
  • Loading branch information
@IanButterworth
IanButterworth committed Oct 6, 2024
1 parent ab6df86 commit 86a6aa1
Show file tree
Hide file tree
Showing 3 changed files with 60 additions and 30 deletions.
3 changes: 3 additions & 0 deletions base/Base.jl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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")

Expand Down
11 changes: 11 additions & 0 deletions base/task.jl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1098,7 +1098,18 @@ 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
end
# TODO: grow the array if needed i.e. if a thread is added within the `@timed` block
end
catch
undo(ccall(:jl_get_next_task, Ref{Task}, ()))
rethrow()
Expand Down
76 changes: 46 additions & 30 deletions base/timing.jl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -196,17 +196,19 @@ 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)
sched_thresh = 0.1
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 > sched_thresh || lock_conflicts > 0 || compile_time > 0
parens && print(io, " (")
if bytes != 0 || allocs != 0
allocs, ma = prettyprint_getunits(allocs, length(_cnt_units), Int64(1000))
Expand All @@ -223,15 +225,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 > sched_thresh
if bytes != 0 || allocs != 0 || gctime > 0
print(io, ", ")
end
print(io, Ryu.writefixed(Float64(100*wall_time_sched_perc), 2), "% scheduling time")
end
if lock_conflicts > 0
if bytes != 0 || allocs != 0 || gctime > 0 || wall_time_sched_perc > sched_thresh
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 > sched_thresh || lock_conflicts > 0
print(io, ", ")
end
print(io, Ryu.writefixed(Float64(100*compile_time/elapsedtime), 2), "% compilation time")
Expand Down Expand Up @@ -346,7 +354,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
Expand Down Expand Up @@ -600,29 +608,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

0 comments on commit 86a6aa1

Please sign in to comment.