Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add complement function #99

Merged
merged 2 commits into from
Nov 1, 2020
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
40 changes: 40 additions & 0 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
23 changes: 22 additions & 1 deletion src/TimerOutput.jl
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand All @@ -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)

Expand Down
11 changes: 11 additions & 0 deletions test/runtests.jl
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down