diff --git a/README.md b/README.md index b22e0a4..e153a6f 100644 --- a/README.md +++ b/README.md @@ -300,6 +300,46 @@ julia> print_timer() The default timer object can be retrieved with `TimerOutputs.get_defaulttimer()`. +## Measuring time consumed outside `@timeit` blocks + +Often, operations that we do not consider time consuming turn out 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.1" sleep(0.1) + sleep(0.01) +end + +TimerOutputs.complement!(to) +``` + +We can print the result: + +```julia +julia> print_timer(to) + ─────────────────────────────────────────────────────────────────────── + Time Allocations + ────────────────────── ─────────────────────── + Tot / % measured: 144ms / 100% 6.11KiB / 22.0% + + Section ncalls time %tot avg alloc %tot avg + ─────────────────────────────────────────────────────────────────────── + section2 1 120ms 83.6% 120ms 1.17KiB 87.2% 1.17KiB + section2.1 1 106ms 73.9% 106ms 176B 12.8% 176B + ~section2~ 1 13.9ms 9.69% 13.9ms 1.00KiB 74.4% 1.00KiB + section1 1 23.4ms 16.4% 23.4ms 176B 12.8% 176B + ─────────────────────────────────────────────────────────────────────── +``` + +In order to complement the default timer simply call `TimerOuputs.complement!()`. ## Overhead diff --git a/src/TimerOutput.jl b/src/TimerOutput.jl index 324bb86..c9855e5 100644 --- a/src/TimerOutput.jl +++ b/src/TimerOutput.jl @@ -308,7 +308,6 @@ function _flatten!(to::TimerOutput, inner_timers::Dict{String,TimerOutput}) end end - enable_timer!(to::TimerOutput=DEFAULT_TIMER) = to.enabled = true disable_timer!(to::TimerOutput=DEFAULT_TIMER) = to.enabled = false @@ -321,6 +320,28 @@ 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) + 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 + 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) diff --git a/test/runtests.jl b/test/runtests.jl index 1b23837..73b91b6 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -305,6 +305,17 @@ baz(1, 2.0) @test "sleep" in keys(to_debug.inner_timers["baz"].inner_timers) TimerOutputs.disable_debug_timings(@__MODULE__) +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["~section2~"]) == 1 + end # testset struct Simulation