From 1e6ca1e221407ce787413ecd662e515f82dfecd6 Mon Sep 17 00:00:00 2001 From: Joaquim Dias Garcia Date: Fri, 23 Nov 2018 09:08:29 -0200 Subject: [PATCH 1/3] Add complement function --- src/TimerOutput.jl | 21 ++++++++++++++++++++- 1 file changed, 20 insertions(+), 1 deletion(-) diff --git a/src/TimerOutput.jl b/src/TimerOutput.jl index 64d45f1..7bf3a62 100644 --- a/src/TimerOutput.jl +++ b/src/TimerOutput.jl @@ -251,5 +251,24 @@ function _flatten!(to::TimerOutput, inner_timers::Dict{String,TimerOutput}) end end - +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) + end + tot_time = max(tot_time, 0) + tot_allocs = max(tot_allocs, 0) + if !(to.name in ["root", "Flattened"]) + name = "Extra "*to.name + timer = TimerOutput(to.start_data, TimeData(max(1,to.accumulated_data.ncalls), tot_time, tot_allocs), Dict{String,TimerOutput}(), TimerOutput[], name, false, (tot_time, tot_allocs), to.name, to) + to.inner_timers[name] = timer + end + return nothing +end From b2f940e9d06f4a3c33f27abbe900741ea2e1fdb6 Mon Sep 17 00:00:00 2001 From: Joaquim Garcia Date: Sun, 7 Apr 2019 21:29:42 -0300 Subject: [PATCH 2/3] Add test and docs --- README.md | 40 ++++++++++++++++++++++++++++++++++++++++ src/TimerOutput.jl | 7 ++++--- test/runtests.jl | 12 ++++++++++++ 3 files changed, 56 insertions(+), 3 deletions(-) diff --git a/README.md b/README.md index bb7e477..d29b053 100644 --- a/README.md +++ b/README.md @@ -291,6 +291,46 @@ julia> print_timer() The default timer object can be retrieved with `TimerOutputs.get_defaulttimer()`. +## Measuring time consumed outside `@timeit` blocks + +Many times operations that we do not consider time consuming turn to be relevant. +However, adding additional timming blocks just to time initializations and other +less important calls is annoying. + +The `TimerOutputs.complement!()` function can be used to modify a timer and add +values for complement of timed sections. For instance: + +```julia +to = TimerOutput() + +@timeit to "section1" sleep(0.02) +@timeit to "section2" begin + @timeit to "section2" sleep(0.1) + sleep(0.01) +end + +TimerOuputs.complement!(to) +``` + +We cna print the result: + +```julia +julia> print_timer(to) +─────────────────────────────────────────────────────────────────────────── + Time Allocations + ────────────────────── ─────────────────────── + Tot / % measured: 186ms / 81.3% 3.00MiB / 0.05% + + Section ncalls time %tot avg alloc %tot avg + ─────────────────────────────────────────────────────────────────────────── + section2 1 127ms 84.0% 127ms 1.28KiB 85.4% 1.28KiB + section2.1 1 110ms 72.3% 110ms - 14.6% - + Extra section2 1 17.7ms 11.7% 17.7ms 1.06KiB 70.8% 1.06KiB + section1 1 24.3ms 16.0% 24.3ms - 14.6% - + ─────────────────────────────────────────────────────────────────────────── +``` + +In order to complement the default timer simply call `TimerOuputs.complement!()`. ## Overhead diff --git a/src/TimerOutput.jl b/src/TimerOutput.jl index 7bf3a62..473c476 100644 --- a/src/TimerOutput.jl +++ b/src/TimerOutput.jl @@ -251,7 +251,8 @@ function _flatten!(to::TimerOutput, inner_timers::Dict{String,TimerOutput}) end end -function complement(to::TimerOutput) +complement!() = complement!(DEFAULT_TIMER) +function complement!(to::TimerOutput) if length(to.inner_timers) == 0 return nothing end @@ -260,7 +261,7 @@ function complement(to::TimerOutput) for timer in values(to.inner_timers) tot_time -= timer.accumulated_data.time tot_allocs -= timer.accumulated_data.allocs - complement(timer) + complement!(timer) end tot_time = max(tot_time, 0) tot_allocs = max(tot_allocs, 0) @@ -269,6 +270,6 @@ function complement(to::TimerOutput) timer = TimerOutput(to.start_data, TimeData(max(1,to.accumulated_data.ncalls), tot_time, tot_allocs), Dict{String,TimerOutput}(), TimerOutput[], name, false, (tot_time, tot_allocs), to.name, to) to.inner_timers[name] = timer end - return nothing + return to end diff --git a/test/runtests.jl b/test/runtests.jl index 3174a5b..b125025 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -262,4 +262,16 @@ end continue_test() @test isempty(to_continue.inner_timers["x"].inner_timers["test"].inner_timers) + +to = TimerOutput() +@timeit to "section1" sleep(0.02) +@timeit to "section2" begin + @timeit to "section2.1" sleep(0.1) + sleep(0.01) +end +TimerOutputs.complement!(to) + +tom = flatten(to) +@test ncalls(tom["Extra section2"]) == 1 + end # testset From 6b1988591e6390fd3a4ef19a8730705bcc1124d7 Mon Sep 17 00:00:00 2001 From: Joaquim Garcia Date: Sun, 7 Apr 2019 21:54:41 -0300 Subject: [PATCH 3/3] Add only leaves option --- README.md | 15 +++++++++++++++ src/TimerOutput.jl | 26 +++++++++++++------------- test/runtests.jl | 12 ++++++++++++ 3 files changed, 40 insertions(+), 13 deletions(-) diff --git a/README.md b/README.md index 8fbb3b2..4c2b529 100644 --- a/README.md +++ b/README.md @@ -183,6 +183,21 @@ julia> show(to_flatten; compact = true, allocations = false) ────────────────────────────────── ``` +It is also possible to only include leave timer values when flattening. +That is only timmers in the innermost level will be shown. + +```julia +julia> to_flatten = TimerOutputs.flatten(to, only_leaves); + +julia> show(to_flatten; compact = true, allocations = false) + ────────────────────────────────── + Section ncalls time %tot + ────────────────────────────────── + level 2.2 21 525ms 47.5% + level 2.1 31 436ms 39.5% + ────────────────────────────────── +``` + ## Resetting A timer is reset by calling `reset_timer!(to::TimerOutput)`. This will remove all sections and reset the start of the timer to the current time / allocation values. diff --git a/src/TimerOutput.jl b/src/TimerOutput.jl index 5f9cb6c..a08d3cd 100644 --- a/src/TimerOutput.jl +++ b/src/TimerOutput.jl @@ -267,29 +267,29 @@ 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) +function flatten(to::TimerOutput; only_leaves::Bool = false) t, b = totmeasured(to) inner_timers = Dict{String,TimerOutput}() for inner_timer in values(to.inner_timers) - _flatten!(inner_timer, inner_timers) + _flatten!(inner_timer, inner_timers, only_leaves) end toc = copy(to) return TimerOutput(toc.start_data, toc.accumulated_data, inner_timers, TimerOutput[], "Flattened", true, (t, b), "", to) end - -function _flatten!(to::TimerOutput, inner_timers::Dict{String,TimerOutput}) +function _flatten!(to::TimerOutput, inner_timers::Dict{String,TimerOutput}, only_leaves::Bool) for inner_timer in values(to.inner_timers) - _flatten!(inner_timer, inner_timers) + _flatten!(inner_timer, inner_timers, only_leaves) end - - if haskey(inner_timers, to.name) - timer = inner_timers[to.name] - timer.accumulated_data += to.accumulated_data - else - toc = copy(to) - toc.inner_timers = Dict{String,TimerOutput}() - inner_timers[toc.name] = toc + if !only_leaves || isempty(to.inner_timers) + if haskey(inner_timers, to.name) + timer = inner_timers[to.name] + timer.accumulated_data += to.accumulated_data + else + toc = copy(to) + toc.inner_timers = Dict{String,TimerOutput}() + inner_timers[toc.name] = toc + end end end diff --git a/test/runtests.jl b/test/runtests.jl index 7d1d0d4..78f6438 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -314,4 +314,16 @@ TimerOutputs.complement!(to) tom = flatten(to) @test ncalls(tom["Extra section2"]) == 1 +to = TimerOutput() +@timeit to "section1" sleep(0.02) +@timeit to "section2" begin + @timeit to "section2.1" sleep(0.1) + sleep(0.01) +end +TimerOutputs.complement!(to) + +tom = flatten(to, only_leaves = true) +@test ncalls(tom["Extra section2"]) == 1 +@test !haskey(tom, "section2") + end # testset