From 612db133ca601f868df7e8d678439559d6a43438 Mon Sep 17 00:00:00 2001 From: Valentin Churavy Date: Mon, 21 Aug 2023 16:24:13 -0400 Subject: [PATCH 1/2] progress --- Project.toml | 6 +- src/TimerOutput.jl | 397 +++++++++++++++----------------------------- src/TimerOutputs.jl | 9 +- src/show.jl | 32 ++-- src/utilities.jl | 21 +-- 5 files changed, 167 insertions(+), 298 deletions(-) diff --git a/Project.toml b/Project.toml index 75a700a..7461473 100644 --- a/Project.toml +++ b/Project.toml @@ -1,14 +1,16 @@ name = "TimerOutputs" uuid = "a759f4b9-e2f1-59dc-863e-4aeb61b1ea8f" -version = "0.5.23" +version = "0.6.0" [deps] ExprTools = "e2ba6199-217a-4e67-a87a-7c52f15ade04" Printf = "de0858da-6303-5e67-8744-51eddeeeb8d7" +ScopedValues = "7e506255-f358-4e82-b7e4-beb19740aa63" [compat] ExprTools = "0.1.0" -julia = "1" +ScopedValues = "1.0.0" +julia = "1.8" [extras] Test = "8dfed614-e22c-5e08-85e1-65c5234f0b40" diff --git a/src/TimerOutput.jl b/src/TimerOutput.jl index 06379a6..186b80c 100644 --- a/src/TimerOutput.jl +++ b/src/TimerOutput.jl @@ -1,112 +1,105 @@ ############ # TimeData # ############ -mutable struct TimeData - ncalls::Int +struct TimeData + ncalls::Int64 time::Int64 allocs::Int64 - firstexec::Int64 end -TimeData(ncalls, time, allocs) = TimeData(ncalls, time, allocs, time) -Base.copy(td::TimeData) = TimeData(td.ncalls, td.time, td.allocs) -TimeData() = TimeData(0, 0, 0, time_ns()) +TimeData() = TimeData(0,0,0) function Base.:+(self::TimeData, other::TimeData) - TimeData(self.ncalls + other.ncalls, + TimeData(self.ncalls + self.ncalls, self.time + other.time, - self.allocs + other.allocs, - min(self.firstexec, other.firstexec)) + self.allocs + other.allocs) end +mutable struct LList{T} + const next::LList{T} + const val::T + LList{T}() where T = new{T}() + LList(next::LList{T}, val::T) where T = new{T}(next, val) +end + +function Base.show(io::IO, list::LList) + print(io, LList, "(") + first = true + while isdefined(list, :next) + first || print(io, ", ") + first = false + show(io, list.val) + list = list.next + end + print(io, ")") +end + +function Base.iterate(list::LList{T}, state::Union{Nothing, LList{T}}=nothing) where T + if state === nothing + state = list + end + if !isdefined(state, :next) + return nothing + end + return (state.val, state.next) +end + +Base.eltype(::LList{T}) where T = T +Base.IteratorSize(::Type{<:LList}) = Base.SizeUnknown() + + ############### # TimerOutput # ############### mutable struct TimerOutput - start_data::TimeData - accumulated_data::TimeData - inner_timers::Dict{String,TimerOutput} - timer_stack::Vector{TimerOutput} - name::String - flattened::Bool - enabled::Bool - totmeasured::Tuple{Int64,Int64} - prev_timer_label::String - prev_timer::Union{TimerOutput,Nothing} - - function TimerOutput(label::String = "root") - start_data = TimeData(0, time_ns(), gc_bytes()) - accumulated_data = TimeData() - inner_timers = Dict{String,TimerOutput}() - timer_stack = TimerOutput[] - return new(start_data, accumulated_data, inner_timers, timer_stack, label, false, true, (0, 0), "", nothing) - end - - # Jeez... - TimerOutput(start_data, accumulated_data, inner_timers, timer_stack, name, flattened, enabled, totmeasured, prev_timer_label, - prev_timer) = new(start_data, accumulated_data, inner_timers, timer_stack, name, flattened, enabled, totmeasured, prev_timer_label, - prev_timer) + const name::String + const parent::Union{Nothing, TimerOutput} + @atomic data::Union{Nothing, TimeData} + @atomic children::LList{TimerOutput} end - -Base.copy(to::TimerOutput) = TimerOutput(copy(to.start_data), copy(to.accumulated_data), copy(to.inner_timers), - copy(to.timer_stack), to.name, to.flattened, to.enabled, to.totmeasured, "", nothing) - -const DEFAULT_TIMER = TimerOutput() -const _timers = Dict{String, TimerOutput}("Default" => DEFAULT_TIMER) -const _timers_lock = ReentrantLock() # needed for adding new timers on different threads -""" - get_timer(name::String) - -Returns the `TimerOutput` associated with `name`. -If no timers are associated with `name`, a new `TimerOutput` will be created. -""" -function get_timer(name::String) - lock(_timers_lock) do - if !haskey(_timers, name) - _timers[name] = TimerOutput(name) - end - return _timers[name] - end +function TimerOutput(name::String = "root", parent=nothing) + return TimerOutput(name, parent, nothing, LList{TimerOutput}()) end -# push! and pop! -function Base.push!(to::TimerOutput, label::String) - if length(to.timer_stack) == 0 # Root section - current_timer = to - else # Not a root section - current_timer = to.timer_stack[end] +# function Base.show(io::IO, to::TimerOutput) +# print(io, TimerOutput, "(") +# show(io, to.name) +# print(io, ", ") +# show(io, @atomic(to.data)) +# print(io, ", ") +# show(io, @atomic(to.children)) +# print(io, ")") +# end + +const TIMER = ScopedValue(TimerOutput()) + + +function register!(to::TimerOutput) + # Note: Don't call register twice + parent = to.parent + if parent === nothing + return false end - # Fast path - if current_timer.prev_timer_label == label - timer = current_timer.prev_timer - else - maybe_timer = get(current_timer.inner_timers, label, nothing) - # this could be implemented more elegant using - # get!(() -> TimerOutput(label), current_timer.inner_timers, label) - # however that causes lots of allocations in - # julia v1.3 - if maybe_timer === nothing - timer = TimerOutput(label) - current_timer.inner_timers[label] = timer - else - timer = maybe_timer - end + success = false + old = @atomic :acquire parent.children + while !success + new = LList(old, to) + old, success = @atomicreplace :acquire_release :acquire parent.children old => new end - timer = timer::TimerOutput - current_timer.prev_timer_label = label - current_timer.prev_timer = timer - - push!(to.timer_stack, timer) - return timer.accumulated_data + return true end -Base.pop!(to::TimerOutput) = pop!(to.timer_stack) +function finish!(to::TimerOutput, t₀, b₀) + data = TimeData(1, time_ns() - t₀, gc_bytes() - b₀) + @atomic to.data = data + register!(to) +end # Only sum the highest parents function totmeasured(to::TimerOutput) t, b = Int64(0), Int64(0) - for section in values(to.inner_timers) - timedata = section.accumulated_data + for child in to.children + timedata = child.data t += timedata.time b += timedata.allocs end @@ -115,59 +108,30 @@ end function longest_name(to::TimerOutput, indent = 0) m = textwidth(to.name) + indent - for inner_timer in values(to.inner_timers) - m = max(m, longest_name(inner_timer, indent + 2)) + for child in to.children + m = max(m, longest_name(child, indent + 2)) end return m end - -# merging timer outputs -const merge_lock = ReentrantLock() # needed for merges of objects on different threads - -Base.merge(others::TimerOutput...) = merge!(TimerOutput(), others...) -function Base.merge!(self::TimerOutput, others::TimerOutput...; tree_point = String[]) - lock(merge_lock) do - for other in others - self.accumulated_data += other.accumulated_data - its = self.inner_timers - for point in tree_point - its = its[point].inner_timers - end - _merge(its, other.inner_timers) - end - return self - end -end -function _merge(self::Dict{String,TimerOutput}, other::Dict{String,TimerOutput}) - for key in keys(other) - if haskey(self, key) - self[key].accumulated_data += other[key].accumulated_data - _merge(self[key].inner_timers, other[key].inner_timers) - else - self[key] = deepcopy(other[key]) - end - end -end - ####### # API # ####### # Accessors -ncalls(to::TimerOutput) = to.accumulated_data.ncalls -allocated(to::TimerOutput) = to.accumulated_data.allocs -time(to::TimerOutput) = to.accumulated_data.time +ncalls(to::TimerOutput) = to.data.ncalls +allocated(to::TimerOutput) = to.data.allocs +time(to::TimerOutput) = to._data.time totallocated(to::TimerOutput) = totmeasured(to)[2] tottime(to::TimerOutput) = totmeasured(to)[1] -time() = time(DEFAULT_TIMER) -ncalls() = ncalls(DEFAULT_TIMER) -allocated() = allocated(DEFAULT_TIMER) -totallocated() = totmeasured(DEFAULT_TIMER)[2] -tottime() = totmeasured(DEFAULT_TIMER)[1] +time() = time(TIMER[]) +ncalls() = ncalls(TIMER[]) +allocated() = allocated(TIMER[]) +totallocated() = totmeasured(TIMER[])[2] +tottime() = totmeasured(TIMER[])[1] -get_defaulttimer() = DEFAULT_TIMER +get_defaulttimer() = TIMER[] Base.@deprecate get_defaultimer get_defaulttimer # Macro @@ -194,7 +158,7 @@ function disable_debug_timings(m::Module) end end -timer_expr(args...) = throw(ArgumentError("invalid macro usage for @timeit, use as @timeit [to] label codeblock")) +timer_expr(args...) = throw(ArgumentError("invalid macro usage for @timeit, use as @timeit label codeblock")) function is_func_def(f) if isa(f, Expr) && (f.head === :function || Base.is_short_function_def(f)) @@ -205,44 +169,31 @@ function is_func_def(f) end function timer_expr(m::Module, is_debug::Bool, ex::Expr) - is_func_def(ex) && return timer_expr_func(m, is_debug, :($(TimerOutputs.DEFAULT_TIMER)), ex) - return esc(_timer_expr(m, is_debug, :($(TimerOutputs).DEFAULT_TIMER), ex)) + is_func_def(ex) && return timer_expr_func(m, is_debug, ex, nothing) + error("invalid macro usage for @timeit") end -function timer_expr(m::Module, is_debug::Bool, label_or_to, ex::Expr) - is_func_def(ex) && return timer_expr_func(m, is_debug, label_or_to, ex) - return esc(_timer_expr(m, is_debug, :($(TimerOutputs).DEFAULT_TIMER), label_or_to, ex)) +function timer_expr(m::Module, is_debug::Bool, label, ex::Expr) + timer_expr(m, is_debug, string(label), ex) end function timer_expr(m::Module, is_debug::Bool, label::String, ex::Expr) - is_func_def(ex) && return timer_expr_func(m, is_debug, :($(TimerOutputs).DEFAULT_TIMER), ex, label) - return esc(_timer_expr(m, is_debug, :($(TimerOutputs).DEFAULT_TIMER), label, ex)) -end - -function timer_expr(m::Module, is_debug::Bool, to, label, ex::Expr) - is_func_def(ex) && return timer_expr_func(m, is_debug, to, ex, label) - return esc(_timer_expr(m, is_debug, to, label, ex)) + is_func_def(ex) && return timer_expr_func(m, is_debug, ex, label) + return esc(_timer_expr(m, is_debug, label, ex)) end -function _timer_expr(m::Module, is_debug::Bool, to::Union{Symbol, Expr, TimerOutput}, label, ex::Expr) - @gensym local_to enabled accumulated_data b₀ t₀ val +function _timer_expr(m::Module, is_debug::Bool, label, ex::Expr) + @gensym b₀ t₀ val timeit_block = quote - $local_to = $to - $enabled = $local_to.enabled - if $enabled - $accumulated_data = $(push!)($local_to, $label) + $scoped($(TIMER) => $(TimerOutput)($label, $(TIMER)[])) do # TODO can we have a macro form of this? + $b₀ = $(gc_bytes)() + $t₀ = $(time_ns)() + $(Expr(:tryfinally, + :($val = $ex), + :($(finish!)($(TIMER)[], $t₀, $b₀)) + )) + $val end - $b₀ = $(gc_bytes)() - $t₀ = $(time_ns)() - $(Expr(:tryfinally, - :($val = $ex), - quote - if $enabled - $(do_accumulate!)($accumulated_data, $t₀, $b₀) - $(pop!)($local_to) - end - end)) - $val end if is_debug @@ -258,7 +209,7 @@ function _timer_expr(m::Module, is_debug::Bool, to::Union{Symbol, Expr, TimerOut end end -function timer_expr_func(m::Module, is_debug::Bool, to, expr::Expr, label=nothing) +function timer_expr_func(m::Module, is_debug::Bool, expr::Expr, label=nothing) expr = macroexpand(m, expr) def = splitdef(expr) @@ -269,132 +220,52 @@ function timer_expr_func(m::Module, is_debug::Bool, to, expr::Expr, label=nothin @inline function inner() $(def[:body]) end - $(_timer_expr(m, is_debug, to, label, :(inner()))) + $(_timer_expr(m, is_debug, label, :(inner()))) end else - _timer_expr(m, is_debug, to, label, def[:body]) + _timer_expr(m, is_debug, label, def[:body]) end return esc(combinedef(def)) end -function do_accumulate!(accumulated_data, t₀, b₀) - accumulated_data.time += time_ns() - t₀ - accumulated_data.allocs += gc_bytes() - b₀ - accumulated_data.ncalls += 1 -end - - -reset_timer!() = reset_timer!(DEFAULT_TIMER) +reset_timer!() = reset_timer!(TIMER[]) function reset_timer!(to::TimerOutput) - to.inner_timers = Dict{String,TimerOutput}() - to.start_data = TimeData(0, time_ns(), gc_bytes()) - to.accumulated_data = TimeData() - to.prev_timer_label = "" - to.prev_timer = nothing - resize!(to.timer_stack, 0) + @atomic to.data = nothing + @atomic to.children = LList{TimerOutput}() return to end -# We can remove this now that the @timeit macro is exception safe. -# Doesn't hurt to keep it for a while though -timeit(f::Function, label::String) = timeit(f, DEFAULT_TIMER, label) -function timeit(f::Function, to::TimerOutput, label::String) - accumulated_data = push!(to, label) - b₀ = gc_bytes() - t₀ = time_ns() - local val - try - val = f() - finally - accumulated_data.time += time_ns() - t₀ - accumulated_data.allocs += gc_bytes() - b₀ - accumulated_data.ncalls += 1 - pop!(to) - end - return val -end - -Base.haskey(to::TimerOutput, name::String) = haskey(to.inner_timers, name) -Base.getindex(to::TimerOutput, name::String) = to.inner_timers[name] - -function flatten(to::TimerOutput) - t, b = totmeasured(to) - inner_timers = Dict{String,TimerOutput}() - for inner_timer in values(to.inner_timers) - _flatten!(inner_timer, inner_timers) - end - toc = copy(to) - return TimerOutput(toc.start_data, toc.accumulated_data, inner_timers, TimerOutput[], "Flattened", true, true, (t, b), "", to) -end +function merge(self::TimerOutput, other::Union{TimerOutput, Nothing}=nothing) + if other !== nothing + @assert self.parent == other.parent + @assert self.name == other.name - -function _flatten!(to::TimerOutput, inner_timers::Dict{String,TimerOutput}) - for inner_timer in values(to.inner_timers) - _flatten!(inner_timer, inner_timers) - end - - if haskey(inner_timers, to.name) - timer = inner_timers[to.name] - timer.accumulated_data += to.accumulated_data + data = self.data + other.data else - toc = copy(to) - toc.inner_timers = Dict{String,TimerOutput}() - inner_timers[toc.name] = toc + data = self.data end -end - -enable_timer!(to::TimerOutput=DEFAULT_TIMER) = to.enabled = true -disable_timer!(to::TimerOutput=DEFAULT_TIMER) = to.enabled = false - -# Macro to selectively disable timer for expression -macro notimeit(args...) - notimeit_expr(args...) -end - -# Default function throws an error for the benefit of the user -notimeit_expr(args...) = throw(ArgumentError("invalid macro usage for @notimeit, use as @notimeit [to] codeblock")) - -complement!() = complement!(DEFAULT_TIMER) -function complement!(to::TimerOutput) - if length(to.inner_timers) == 0 - return nothing - end - tot_time = to.accumulated_data.time - tot_allocs = to.accumulated_data.allocs - for timer in values(to.inner_timers) - tot_time -= timer.accumulated_data.time - tot_allocs -= timer.accumulated_data.allocs - complement!(timer) + accum = Dict{String, TimerOutput}() + for child in self.children + if !haskey(accum, child.name) + accum[child.name] = merge(child) + continue + end + accum[child.name] = merge(accum[child.name], child) end - tot_time = max(tot_time, 0) - tot_allocs = max(tot_allocs, 0) - if !(to.name in ["root", "Flattened"]) - name = string("~", to.name, "~") - timer = TimerOutput(to.start_data, TimeData(max(1,to.accumulated_data.ncalls), tot_time, tot_allocs), Dict{String,TimerOutput}(), TimerOutput[], name, false, true, (tot_time, tot_allocs), to.name, to) - to.inner_timers[name] = timer + if other !== nothing + for child in other.children + if !haskey(accum, child.name) + accum[child.name] = merge(child) + continue + end + accum[child.name] = merge(accum[child.name], child) + end end - return to -end - -# If @notimeit was called without a TimerOutput instance, use default timer -notimeit_expr(ex::Expr) = notimeit_expr(:($(TimerOutputs.DEFAULT_TIMER)), ex) - -# Disable timer, evaluate expression, restore timer to previous value, and return expression result -function notimeit_expr(to, ex::Expr) - return quote - local to = $(esc(to)) - local enabled = to.enabled - $(disable_timer!)(to) - local val - $(Expr(:tryfinally, - :(val = $(esc(ex))), - quote - if enabled - $(enable_timer!)(to) - end - end)) - val + list = LList{TimerOutput}() + for child in values(accum) + list = LList(list, child) end + return TimerOutput(self.name, self.parent, data, list) end diff --git a/src/TimerOutputs.jl b/src/TimerOutputs.jl index 1145e00..cf8fd0d 100644 --- a/src/TimerOutputs.jl +++ b/src/TimerOutputs.jl @@ -1,6 +1,7 @@ module TimerOutputs using ExprTools +using ScopedValues import Base: show, time_ns export TimerOutput, @timeit, @timeit_debug, reset_timer!, print_timer, timeit, @@ -24,10 +25,10 @@ include("TimerOutput.jl") include("show.jl") include("utilities.jl") -if Base.VERSION >= v"1.4.2" - include("compile.jl") - _precompile_() -end +# if Base.VERSION >= v"1.4.2" +# include("compile.jl") +# _precompile_() +# end function __init__() # Reset DEFAULT_TIMER; otherwise starting time is the time of precompile diff --git a/src/show.jl b/src/show.jl index c9d2b47..b4172e9 100644 --- a/src/show.jl +++ b/src/show.jl @@ -4,15 +4,21 @@ print_timer(io::IO; kwargs...) = print_timer(io, DEFAULT_TIMER; kwargs...) print_timer(io::IO, to::TimerOutput; kwargs...) = (show(io, to; kwargs...); println(io)) Base.show(to::TimerOutput; kwargs...) = show(stdout, to; kwargs...) -function Base.show(io::IO, to::TimerOutput; allocations::Bool = true, sortby::Symbol = :time, linechars::Symbol = :unicode, compact::Bool = false, title::String = "") - sortby in (:time, :ncalls, :allocations, :name, :firstexec) || throw(ArgumentError("sortby should be :time, :allocations, :ncalls, :name, or :firstexec, got $sortby")) +function Base.show(io::IO, to::TimerOutput; + allocations::Bool = true, sortby::Symbol = :time, linechars::Symbol = :unicode, + compact::Bool = false, title::String = "") + + sortby in (:time, :ncalls, :allocations, :name) || throw(ArgumentError("sortby should be :time, :allocations, :ncalls, :name, got $sortby")) linechars in (:unicode, :ascii) || throw(ArgumentError("linechars should be :unicode or :ascii, got $linechars")) - t₀, b₀ = to.start_data.time, to.start_data.allocs - t₁, b₁ = time_ns(), gc_bytes() - Δt, Δb = t₁ - t₀, b₁ - b₀ - ∑t, ∑b = to.flattened ? to.totmeasured : totmeasured(to) + to = merge(to) + if to.data !== nothing + Δt, Δb = to.data.time, to.data.allocs + else + Δt, Δb = 0, 0 + end + ∑t, ∑b = totmeasured(to) max_name = longest_name(to) available_width = displaysize(io)[2] requested_width = max_name @@ -37,7 +43,7 @@ function Base.show(io::IO, to::TimerOutput; allocations::Bool = true, sortby::Sy print_header(io, Δt, Δb, ∑t, ∑b, name_length, true, allocations, linechars, compact, title) rev = !in(sortby, [:name, :firstexec]) by(x) = sortf(x, sortby) - for timer in sort!(collect(values(to.inner_timers)); rev = rev, by = by) + for timer in sort!(collect(to.children); rev = rev, by = by) _print_timer(io, timer, ∑t, ∑b, 0, name_length, allocations, sortby, compact) end print_header(io, Δt, Δb, ∑t, ∑b, name_length, false, allocations, linechars, compact, title) @@ -137,13 +143,13 @@ function print_header(io, Δt, Δb, ∑t, ∑b, name_length, header, allocations end function _print_timer(io::IO, to::TimerOutput, ∑t::Integer, ∑b::Integer, indent::Integer, name_length, allocations, sortby, compact) - accum_data = to.accumulated_data - t = accum_data.time - b = accum_data.allocs + data = to.data + t = data.time + b = data.allocs name = truncdots(to.name, name_length - indent) print(io, " ") - nc = accum_data.ncalls + nc = data.ncalls print(io, " "^indent, rpad(name, name_length + 2 - indent)) print(io, lpad(prettycount(nc), 5, " ")) @@ -158,9 +164,9 @@ function _print_timer(io::IO, to::TimerOutput, ∑t::Integer, ∑b::Integer, ind end print(io, "\n") - rev = !in(sortby, [:name, :firstexec]) + rev = !in(sortby, [:name,]) by(x) = sortf(x, sortby) - for timer in sort!(collect(values(to.inner_timers)); rev = rev, by = by) + for timer in sort!(collect(to.children); rev = rev, by = by) _print_timer(io, timer, ∑t, ∑b, indent + 2, name_length, allocations, sortby, compact) end end diff --git a/src/utilities.jl b/src/utilities.jl index 9c7a703..e890fa5 100644 --- a/src/utilities.jl +++ b/src/utilities.jl @@ -120,12 +120,11 @@ Converts a `TimerOutput` into a nested set of dictionaries, with keys and value """ function todict(to::TimerOutput) return Dict{String,Any}( - "n_calls" => ncalls(to), "time_ns" => time(to), "allocated_bytes" => allocated(to), "total_allocated_bytes" => totallocated(to), "total_time_ns" => tottime(to), - "inner_timers" => Dict{String, Any}(k => todict(v) for (k,v) in to.inner_timers) + # "inner_timers" => Dict{String, Any}(k => todict(v) for (k,v) in to.inner_timers) ) end @@ -138,7 +137,6 @@ end # you that `f` is involved). struct InstrumentedFunction{F} <: Function func::F - t::TimerOutput name::String end @@ -150,17 +148,8 @@ function funcname(f::F) where {F} end end -InstrumentedFunction(f, t) = InstrumentedFunction(f, t, funcname(f)) +InstrumentedFunction(f) = InstrumentedFunction(f, funcname(f)) -function (inst::InstrumentedFunction)(args...; kwargs...) - @timeit inst.t inst.name inst.func(args...; kwargs...) -end - -""" - (t::TimerOutput)(f, name=string(repr(f))) -> InstrumentedFunction - -Instruments `f` by the [`TimerOutput`](@ref) `t` returning an `InstrumentedFunction`. -This function can be used just like `f`, but whenever it is called it stores timing -results in `t`. -""" -(t::TimerOutput)(f, name=funcname(f)) = InstrumentedFunction(f, t, name) +# function (inst::InstrumentedFunction)(args...; kwargs...) +# @timeit inst.name inst.func(args...; kwargs...) +# end From e0eb1666d386dec3609e48ab469a8fac305239f6 Mon Sep 17 00:00:00 2001 From: Valentin Churavy Date: Mon, 21 Aug 2023 17:34:21 -0400 Subject: [PATCH 2/2] Finish port to ScopedValues --- src/TimerOutput.jl | 33 +++------------------------------ src/TimerOutputs.jl | 8 ++++---- src/compile.jl | 12 ++++-------- src/show.jl | 38 ++++++++++++++++---------------------- 4 files changed, 27 insertions(+), 64 deletions(-) diff --git a/src/TimerOutput.jl b/src/TimerOutput.jl index 186b80c..b59debb 100644 --- a/src/TimerOutput.jl +++ b/src/TimerOutput.jl @@ -57,22 +57,12 @@ mutable struct TimerOutput @atomic children::LList{TimerOutput} end -function TimerOutput(name::String = "root", parent=nothing) +function TimerOutput(name::String = "", parent=nothing) return TimerOutput(name, parent, nothing, LList{TimerOutput}()) end - -# function Base.show(io::IO, to::TimerOutput) -# print(io, TimerOutput, "(") -# show(io, to.name) -# print(io, ", ") -# show(io, @atomic(to.data)) -# print(io, ", ") -# show(io, @atomic(to.children)) -# print(io, ")") -# end - const TIMER = ScopedValue(TimerOutput()) +isroot(to::TimerOutput) = to.parent === nothing function register!(to::TimerOutput) # Note: Don't call register twice @@ -95,17 +85,6 @@ function finish!(to::TimerOutput, t₀, b₀) register!(to) end -# Only sum the highest parents -function totmeasured(to::TimerOutput) - t, b = Int64(0), Int64(0) - for child in to.children - timedata = child.data - t += timedata.time - b += timedata.allocs - end - return t, b -end - function longest_name(to::TimerOutput, indent = 0) m = textwidth(to.name) + indent for child in to.children @@ -122,17 +101,12 @@ end ncalls(to::TimerOutput) = to.data.ncalls allocated(to::TimerOutput) = to.data.allocs time(to::TimerOutput) = to._data.time -totallocated(to::TimerOutput) = totmeasured(to)[2] -tottime(to::TimerOutput) = totmeasured(to)[1] time() = time(TIMER[]) ncalls() = ncalls(TIMER[]) allocated() = allocated(TIMER[]) -totallocated() = totmeasured(TIMER[])[2] -tottime() = totmeasured(TIMER[])[1] -get_defaulttimer() = TIMER[] -Base.@deprecate get_defaultimer get_defaulttimer +current_timer() = TIMER[] # Macro macro timeit(args...) @@ -238,7 +212,6 @@ end function merge(self::TimerOutput, other::Union{TimerOutput, Nothing}=nothing) if other !== nothing - @assert self.parent == other.parent @assert self.name == other.name data = self.data + other.data diff --git a/src/TimerOutputs.jl b/src/TimerOutputs.jl index cf8fd0d..0859d1a 100644 --- a/src/TimerOutputs.jl +++ b/src/TimerOutputs.jl @@ -25,10 +25,10 @@ include("TimerOutput.jl") include("show.jl") include("utilities.jl") -# if Base.VERSION >= v"1.4.2" -# include("compile.jl") -# _precompile_() -# end +if Base.VERSION >= v"1.4.2" + include("compile.jl") + _precompile_() +end function __init__() # Reset DEFAULT_TIMER; otherwise starting time is the time of precompile diff --git a/src/compile.jl b/src/compile.jl index 9d1a5b7..f23ad1c 100644 --- a/src/compile.jl +++ b/src/compile.jl @@ -1,18 +1,14 @@ # To make it less likely that users measure TimerOutputs compilation time. let - to = TimerOutput() - @timeit to "1" string(1) + @timeit "1" string(1) end function _precompile_() ccall(:jl_generating_output, Cint, ()) == 1 || return nothing @assert Base.precompile(Tuple{typeof(print_timer), typeof(stdout), TimerOutput}) @assert Base.precompile(Tuple{typeof(print_timer), TimerOutput}) - @assert Base.precompile(Tuple{typeof(push!), TimerOutput, String}) + @assert Base.precompile(Tuple{typeof(finish!), TimerOutput, Int, Int}) @assert Base.precompile(Tuple{typeof(reset_timer!), TimerOutput}) - @assert Base.precompile(Tuple{typeof(disable_timer!), TimerOutput}) - @assert Base.precompile(Tuple{typeof(enable_timer!), TimerOutput}) - @assert Base.precompile(Tuple{typeof(complement!), TimerOutput}) - @assert Base.precompile(Tuple{typeof(do_accumulate!), TimeData, UInt64, Int64}) - @assert Base.precompile(Tuple{Type{TimerOutput}, String}) + @assert Base.precompile(Tuple{typeof(register!), TimerOutput}) + @assert Base.precompile(Tuple{Type{TimerOutput}, String, TimerOutput}) end diff --git a/src/show.jl b/src/show.jl index b4172e9..5aa0f5d 100644 --- a/src/show.jl +++ b/src/show.jl @@ -12,13 +12,13 @@ function Base.show(io::IO, to::TimerOutput; linechars in (:unicode, :ascii) || throw(ArgumentError("linechars should be :unicode or :ascii, got $linechars")) to = merge(to) - if to.data !== nothing - Δt, Δb = to.data.time, to.data.allocs + if !isroot(to) + data = to.data else - Δt, Δb = 0, 0 + data = sum(child->child.data, to.children, init=TimeData()) end + ∑t, ∑b = data.time, data.allocs - ∑t, ∑b = totmeasured(to) max_name = longest_name(to) available_width = displaysize(io)[2] requested_width = max_name @@ -40,21 +40,20 @@ function Base.show(io::IO, to::TimerOutput; #requested_width = 34 + (allocations ? 27 : 0) + max_name name_length = max(9, max_name - max(0, requested_width - available_width)) - print_header(io, Δt, Δb, ∑t, ∑b, name_length, true, allocations, linechars, compact, title) - rev = !in(sortby, [:name, :firstexec]) + print_header(io, ∑t, ∑b, name_length, true, allocations, linechars, compact, title) + rev = !in(sortby, (:name,)) by(x) = sortf(x, sortby) for timer in sort!(collect(to.children); rev = rev, by = by) _print_timer(io, timer, ∑t, ∑b, 0, name_length, allocations, sortby, compact) end - print_header(io, Δt, Δb, ∑t, ∑b, name_length, false, allocations, linechars, compact, title) + print_header(io, ∑t, ∑b, name_length, false, allocations, linechars, compact, title) end function sortf(x, sortby) - sortby == :time && return x.accumulated_data.time - sortby == :ncalls && return x.accumulated_data.ncalls - sortby == :allocations && return x.accumulated_data.allocs + sortby == :time && return x.data.time + sortby == :ncalls && return x.data.ncalls + sortby == :allocations && return x.data.allocs sortby == :name && return x.name - sortby == :firstexec && return x.accumulated_data.firstexec error("internal error") end @@ -70,7 +69,7 @@ function truncdots(str, n) return String(take!(io)) end -function print_header(io, Δt, Δb, ∑t, ∑b, name_length, header, allocations, linechars, compact, title) +function print_header(io, ∑t, ∑b, name_length, header, allocations, linechars, compact, title) global BOX_MODE, ALLOCATIONS_ENABLED midrule = linechars == :unicode ? "─" : "-" @@ -108,15 +107,10 @@ function print_header(io, Δt, Δb, ∑t, ∑b, name_length, header, allocations end alloc_underline = midrule^textwidth(allocation_header) - #tot_meas_str = string(" ", rpad("Tot / % measured:", textwidth(sec_ncalls) - 1, " ")) - if compact - tot_meas_str = center("Total measured:", textwidth(sec_ncalls)) - else - tot_meas_str = center("Tot / % measured:", textwidth(sec_ncalls)) - end + tot_meas_str = center("Total measured:", textwidth(sec_ncalls)) - str_time = center(string(prettytime(Δt), compact ? "" : string(" / ", prettypercent(∑t, Δt))), textwidth(time_header)) - str_alloc = center(string(prettymemory(Δb), compact ? "" : string(" / ", prettypercent(∑b, Δb))), textwidth(allocation_header)) + str_time = center(prettytime(∑t), textwidth(time_header)) + str_alloc = center(prettymemory(∑b), textwidth(allocation_header)) header_str = string(" time %tot %timed") tot_midstr = string(sec_ncalls, " ", header_str) @@ -146,10 +140,10 @@ function _print_timer(io::IO, to::TimerOutput, ∑t::Integer, ∑b::Integer, ind data = to.data t = data.time b = data.allocs + nc = data.ncalls name = truncdots(to.name, name_length - indent) print(io, " ") - nc = data.ncalls print(io, " "^indent, rpad(name, name_length + 2 - indent)) print(io, lpad(prettycount(nc), 5, " ")) @@ -164,7 +158,7 @@ function _print_timer(io::IO, to::TimerOutput, ∑t::Integer, ∑b::Integer, ind end print(io, "\n") - rev = !in(sortby, [:name,]) + rev = !in(sortby, (:name,)) by(x) = sortf(x, sortby) for timer in sort!(collect(to.children); rev = rev, by = by) _print_timer(io, timer, ∑t, ∑b, indent + 2, name_length, allocations, sortby, compact)