From df4a3de3b8e5388f758309b01b276dee00ee8c00 Mon Sep 17 00:00:00 2001 From: Takafumi Arakaki Date: Sat, 25 Jan 2020 21:04:06 -0800 Subject: [PATCH 1/2] Add progress logging based on ProgressLogging.jl spec --- Project.toml | 2 + src/BenchmarkTools.jl | 2 + src/execution.jl | 128 ++++++++++++++++++++++++++++++++++-------- 3 files changed, 110 insertions(+), 22 deletions(-) diff --git a/Project.toml b/Project.toml index b7464b31..feb1997c 100644 --- a/Project.toml +++ b/Project.toml @@ -4,8 +4,10 @@ version = "0.4.3" [deps] JSON = "682c06a0-de6a-54ab-a142-c8b1cf79cde6" +Logging = "56ddb016-857b-54e1-b83d-db4d58db5568" Printf = "de0858da-6303-5e67-8744-51eddeeeb8d7" Statistics = "10745b16-79ce-11e8-11f9-7d13ad32a3b2" +UUIDs = "cf7118a7-6976-5b1a-9a39-7adc72f591a4" [compat] julia = "≥ 0.7.0" diff --git a/src/BenchmarkTools.jl b/src/BenchmarkTools.jl index 619e493d..a3eb8bbc 100644 --- a/src/BenchmarkTools.jl +++ b/src/BenchmarkTools.jl @@ -3,7 +3,9 @@ module BenchmarkTools using JSON using Base.Iterators +using Logging: @logmsg, LogLevel using Statistics +using UUIDs: uuid4 using Printf diff --git a/src/execution.jl b/src/execution.jl index 9d4f7058..24fb494a 100644 --- a/src/execution.jl +++ b/src/execution.jl @@ -32,6 +32,54 @@ end run_result(b::Benchmark, p::Parameters = b.params; kwargs...) = Base.invokelatest(_run, b, p; kwargs...) lineartrial(b::Benchmark, p::Parameters = b.params; kwargs...) = Base.invokelatest(_lineartrial, b, p; kwargs...) +############################## +# progress logging utilities # +############################## + +# As used in ProgressLogging.jl +# https://github.com/JunoLab/ProgressLogging.jl/blob/v0.1.0/src/ProgressLogging.jl#L11 +const ProgressLevel = LogLevel(-1) + +""" + _withprogress( + name::AbstractString, + group::BenchmarkGroup; + kwargs..., + ) do progressid, nleaves, ndone + ... + end + +Execute do block with following arguments: + +* `progressid`: logging ID to be used for `@logmsg`. +* `nleaves`: total number of benchmarks counted at the root benchmark group. +* `ndone`: number of completed benchmarks + +They are either extracted from `kwargs` (for sub-groups) or newly created +(for root benchmark group). +""" +function _withprogress( + f, + name::AbstractString, + group::BenchmarkGroup; + progressid = nothing, + nleaves = NaN, + ndone = NaN, + _..., +) + if progressid !== nothing + return f(progressid, nleaves, ndone) + end + progressid = uuid4() + nleaves = length(leaves(group)) + @logmsg(ProgressLevel, name, progress = NaN, _id = progressid) + try + return f(progressid, nleaves, 0) + finally + @logmsg(ProgressLevel, name, progress = "done", _id = progressid) + end +end + ############# # execution # ############# @@ -43,21 +91,40 @@ lineartrial(b::Benchmark, p::Parameters = b.params; kwargs...) = Base.invokelate function sample end function _run end -Base.run(b::Benchmark, p::Parameters = b.params; kwargs...) = run_result(b, p; kwargs...)[1] - -function Base.run(group::BenchmarkGroup, args...; verbose::Bool = false, pad = "", kwargs...) - result = similar(group) - gcscrub() # run GC before running group, even if individual benchmarks don't manually GC - i = 1 - for id in keys(group) - verbose && println(pad, "($(i)/$(length(group))) benchmarking ", repr(id), "...") - took_seconds = @elapsed begin - result[id] = run(group[id], args...; verbose = verbose, pad = pad*" ", kwargs...) +Base.run(b::Benchmark, p::Parameters = b.params; progressid=nothing, nleaves=NaN, ndone=NaN, kwargs...) = + run_result(b, p; kwargs...)[1] + +Base.run(group::BenchmarkGroup, args...; verbose::Bool = false, pad = "", kwargs...) = + _withprogress("Benchmarking", group; kwargs...) do progressid, nleaves, ndone + result = similar(group) + gcscrub() # run GC before running group, even if individual benchmarks don't manually GC + i = 1 + for id in keys(group) + progressid === nothing || @logmsg( + ProgressLevel, + "Benchmarking", + progress = ndone / nleaves, + _id = progressid + ) + verbose && + println(pad, "($(i)/$(length(group))) benchmarking ", repr(id), "...") + took_seconds = @elapsed begin + result[id] = run( + group[id], + args...; + verbose = verbose, + pad = pad * " ", + kwargs..., + progressid = progressid, + nleaves = nleaves, + ndone = ndone, + ) + end + ndone += group[id] isa BenchmarkGroup ? length(leaves(group[id])) : 1 + verbose && (println(pad, "done (took ", took_seconds, " seconds)"); i += 1) end - verbose && (println(pad, "done (took ", took_seconds, " seconds)"); i += 1) + return result end - return result -end function _lineartrial(b::Benchmark, p::Parameters = b.params; maxevals = RESOLUTION, kwargs...) params = Parameters(p; kwargs...) @@ -118,18 +185,35 @@ for i in 1:8 (EVALS[((i*1000)+1):((i+1)*1000)] .= 11 - i) end # linearl guessevals(t) = t <= length(EVALS) ? EVALS[t] : 1 -function tune!(group::BenchmarkGroup; verbose::Bool = false, pad = "", kwargs...) - gcscrub() # run GC before running group, even if individual benchmarks don't manually GC - i = 1 - for id in keys(group) - verbose && println(pad, "($(i)/$(length(group))) tuning ", repr(id), "...") - took_seconds = @elapsed tune!(group[id]; verbose = verbose, pad = pad*" ", kwargs...) - verbose && (println(pad, "done (took ", took_seconds, " seconds)"); i += 1) +tune!(group::BenchmarkGroup; verbose::Bool = false, pad = "", kwargs...) = + _withprogress("Tuning", group; kwargs...) do progressid, nleaves, ndone + gcscrub() # run GC before running group, even if individual benchmarks don't manually GC + i = 1 + for id in keys(group) + progressid === nothing || @logmsg( + ProgressLevel, + "Tuning", + progress = ndone / nleaves, + _id = progressid + ) + verbose && println(pad, "($(i)/$(length(group))) tuning ", repr(id), "...") + took_seconds = @elapsed tune!( + group[id]; + verbose = verbose, + pad = pad * " ", + kwargs..., + progressid = progressid, + nleaves = nleaves, + ndone = ndone, + ) + ndone += group[id] isa BenchmarkGroup ? length(leaves(group[id])) : 1 + verbose && (println(pad, "done (took ", took_seconds, " seconds)"); i += 1) + end + return group end - return group -end function tune!(b::Benchmark, p::Parameters = b.params; + progressid=nothing, nleaves=NaN, ndone=NaN, # ignored verbose::Bool = false, pad = "", kwargs...) warmup(b, verbose = false) estimate = ceil(Int, minimum(lineartrial(b, p; kwargs...))) From ca5d00da4219c60c7177255fb58e629bff4006b8 Mon Sep 17 00:00:00 2001 From: Takafumi Arakaki Date: Sun, 26 Jan 2020 16:54:33 -0800 Subject: [PATCH 2/2] Simplify code: no need to guard for `progressid === nothing` ... as `_withprogress` makes sure that it's a `UUID`. --- src/execution.jl | 14 ++------------ 1 file changed, 2 insertions(+), 12 deletions(-) diff --git a/src/execution.jl b/src/execution.jl index 24fb494a..a418a735 100644 --- a/src/execution.jl +++ b/src/execution.jl @@ -100,12 +100,7 @@ Base.run(group::BenchmarkGroup, args...; verbose::Bool = false, pad = "", kwargs gcscrub() # run GC before running group, even if individual benchmarks don't manually GC i = 1 for id in keys(group) - progressid === nothing || @logmsg( - ProgressLevel, - "Benchmarking", - progress = ndone / nleaves, - _id = progressid - ) + @logmsg(ProgressLevel, "Benchmarking", progress = ndone / nleaves, _id = progressid) verbose && println(pad, "($(i)/$(length(group))) benchmarking ", repr(id), "...") took_seconds = @elapsed begin @@ -190,12 +185,7 @@ tune!(group::BenchmarkGroup; verbose::Bool = false, pad = "", kwargs...) = gcscrub() # run GC before running group, even if individual benchmarks don't manually GC i = 1 for id in keys(group) - progressid === nothing || @logmsg( - ProgressLevel, - "Tuning", - progress = ndone / nleaves, - _id = progressid - ) + @logmsg(ProgressLevel, "Tuning", progress = ndone / nleaves, _id = progressid) verbose && println(pad, "($(i)/$(length(group))) tuning ", repr(id), "...") took_seconds = @elapsed tune!( group[id];