diff --git a/README.md b/README.md index 3137079..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. @@ -291,6 +306,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 36c5ecc..a08d3cd 100644 --- a/src/TimerOutput.jl +++ b/src/TimerOutput.jl @@ -267,28 +267,50 @@ 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 !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 - 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 +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) 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 to end diff --git a/test/runtests.jl b/test/runtests.jl index 2a2b745..78f6438 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -272,7 +272,6 @@ end continue_test() @test isempty(to_continue.inner_timers["x"].inner_timers["test"].inner_timers) - # Test @timeit_debug to_debug = TimerOutput() function debug_test() @@ -304,4 +303,27 @@ baz(1, 2.0) @test "baz" in keys(to_debug.inner_timers) @test "sleep" in keys(to_debug.inner_timers["baz"].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 + +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