TimerOutputs

TimerOutputs is a small Julia package that is used to generate formatted output from timings made in different sections of a program. It's main functionality is the @timeit macro, similar to the @time macro in Base except one also assigns a label to the code section being timed. Multiple calls to code sections with the same label (and in the same "scope") will accumulate the data for that label. After the program has executed, it is possible to print a nicely formatted table presenting how much time, allocations and number of calls were made in each section. The output can be customized as to only show the things you are interested in.

If you find this package useful please give it a star. I like stars and it also helps me know where my development time is best spent.

See the changelog for what is new in version 0.5.30.

Example output

An example of the output (used in a finite element simulation) is shown below

──────────────────────────────────────────────────────────────────────────────────────────────────────
                                             Time                             Allocations
                               ────────────────────────────────    ──────────────────────────────────
      Tot / % measured:                 6.89s / 97.8%                       5.20GiB / 84.9%
 ────────────────────────────  ────────────────────────────────    ──────────────────────────────────
 Section               ncalls    time    %tot     avg                alloc    %tot      avg
──────────────────────────────────────────────────────────────────────────────────────────────────────
 assemble                   6   3.27s   48.5%   545ms  ███▉        3.65GiB   82.7%   623MiB  ██████▋
 └─ inner assemble       240k   1.92s   28.5%  8.00μs  ██▎         3.14GiB   71.1%  13.7KiB  █████▊
 linear solve               5   2.73s   40.5%   546ms  ███▎         108MiB    2.4%  21.6MiB  ▎
 create sparse matrix       6   658ms    9.8%   110ms  ▊            662MiB   14.6%   110MiB  █▏
 export                     1  78.4ms    1.2%  78.4ms  ▏           13.1MiB    0.3%  13.1MiB
──────────────────────────────────────────────────────────────────────────────────────────────────────

The Tot / % measured row shows the total (wall) time passed and allocations made since the start of the timer as well as the percentage of those totals spent inside timed sections. The following lines shows data for all the timed sections. The section label is shown first followed by the number of calls made to that section. Finally, the total time elapsed or allocations made in that section are shown together with the percentage of the total in that section and the average (time / allocations per call). The bar columns visualize each section's share of the total; in color-capable terminals they are colored from blue (cheap) to red (expensive). A %par column showing the percentage of the enclosing section is available through the columns printing option, see below.

Usage

The easiest way to show how the package work is with a few examples of timing sections.

using TimerOutputs

# Create a TimerOutput, this is the main type that keeps track of everything.
const to = TimerOutput()

# Time a section code with the label "sleep" to the `TimerOutput` named "to"
@timeit to "sleep" sleep(0.02)

# Create a function to later time
rands() = rand(10^7)

# Time the function, @timeit returns the value being evaluated, just like Base @time
rand_vals = @timeit to "randoms" rands();

# Nested sections (sections with same name are not accumulated
# if they have different parents)
function time_test()
    @timeit to "nest 1" begin
        sleep(0.1)
        # 3 calls to the same label
        @timeit to "level 2.1" sleep(0.03)
        @timeit to "level 2.1" sleep(0.03)
        @timeit to "level 2.1" sleep(0.03)
        @timeit to "level 2.2" sleep(0.2)
    end
    @timeit to "nest 2" begin
        @timeit to "level 2.1" sleep(0.3)
        @timeit to "level 2.2" sleep(0.4)
    end
end

time_test()

# exception safe
function i_will_throw()
    @timeit to "throwing" begin
        sleep(0.5)
        throw(error("this is fine..."))
        print("nope")
    end
end

i_will_throw()

# Use disable_timer! to selectively turn off a timer, enable_timer! turns it on again
disable_timer!(to)
@timeit to "not recorded" sleep(0.1)
enable_timer!(to)

# Use @notimeit to disable timer and re-enable it afterwards (if it was enabled
# before)
@notimeit to time_test()

# Call to a previously used label accumulates data
for i in 1:100
    @timeit to "sleep" sleep(0.01)
end

# Can also annotate function definitions
@timeit to funcdef(x) = x

funcdef(2)

# Timing a function call with no label uses the callee's name as the label,
# i.e. this is shorthand for @timeit to "sum" sum(1:100)
@timeit to sum(1:100)

# @timeit_all additionally times every statement in a block or function body
@timeit_all to function line_profile(n)
    x = 0
    for i in 1:n
        x += i
    end
    x
end

line_profile(10)

# Or to instrument an existing function:
foo(x) = x + 1
timed_foo = to(foo)
timed_foo(5)

# Print the timings in the default way
show(to)

Printing to shows a formatted table showing the number of calls, the total time spent in each section, and the percentage of the time spent in each section since to was created as well as averages (per call). Similar information is available for allocations:

───────────────────────────────────────────────────────────────────────────────────────────────────────────
                                                  Time                             Allocations
                                    ────────────────────────────────    ──────────────────────────────────
         Tot / % measured:                   4.38s / 63.9%                        113MiB / 68.3%
 ─────────────────────────────────  ────────────────────────────────    ──────────────────────────────────
 Section                    ncalls    time    %tot     avg                alloc    %tot      avg
───────────────────────────────────────────────────────────────────────────────────────────────────────────
 sleep                         101   1.16s   41.4%  11.5ms  ███▍        16.7KiB    0.0%     169B
 nest 2                          1   703ms   25.1%   703ms  ██             528B    0.0%     528B
 ├─ level 2.2                    1   402ms   14.3%   402ms  █▏             112B    0.0%     112B
 └─ level 2.1                    1   302ms   10.8%   302ms  ▉              112B    0.0%     112B
 throwing                        1   502ms   17.9%   502ms  █▍             512B    0.0%     512B
 nest 1                          1   399ms   14.2%   399ms  █▏          1.23KiB    0.0%  1.23KiB
 ├─ level 2.2                    1   202ms    7.2%   202ms  ▋              400B    0.0%     400B
 └─ level 2.1                    3  95.8ms    3.4%  31.9ms  ▎              336B    0.0%     112B
 randoms                         1  35.7ms    1.3%  35.7ms  ▏           76.9MiB  100.0%  76.9MiB  ████████
 line_profile @ example.jl       1  8.95μs    0.0%  8.95μs                 480B    0.0%     480B
 ├─ L5: for i = 1:n              1  2.15μs    0.0%  2.15μs                 176B    0.0%     176B
 │  └─ L6: x += i               10   103ns    0.0%  10.3ns                    ∅       ∅        ∅
 └─ L4: x = 0                    1  16.0ns    0.0%  16.0ns                    ∅       ∅        ∅
 sum                             1  22.0ns    0.0%  22.0ns                    ∅       ∅        ∅
 foo                             1  16.0ns    0.0%  16.0ns                    ∅       ∅        ∅
 funcdef                         1  15.0ns    0.0%  15.0ns                    ∅       ∅        ∅
───────────────────────────────────────────────────────────────────────────────────────────────────────────

It is also possible to manually start and stop a timed section.

section = begin_timed_section!(to, "my section")
foo()
end_timed_section!(to, section)

Timing test sets

@timed_testset is a drop-in replacement for Test.@testset that also times each set, so print_timer() after the tests shows where the test time went. Replace @testset with @timed_testset and, at the end of runtests.jl, print the default timer:

using Test, TimerOutputs

@timed_testset "trig" begin
    @timed_testset "sin" begin
        @test sin(0) == 0
    end
    @timed_testset "cos" begin
        @test cos(0) == 1
    end
end

print_timer()  # or e.g. @timed_testset to "trig" begin ... end to use another timer

Test is not a dependency of TimerOutputs; the emitted @testset is resolved at the call site, so using Test there is enough.

Settings for printing:

The print_timer([io::IO = stdout], to::TimerOutput, kwargs), (or show) takes a number of keyword arguments to change the output. They are listed here:

title::String ─ title for the timer
columns::Vector{Symbol} ─ exactly which columns to show, in order. Available: :ncalls, :time, :time_pct, :time_par, :time_avg, :time_min, :time_max, :time_std, :gc_time, :time_bar, :allocs, :allocs_pct, :allocs_par, :allocs_avg, :allocs_bar, and :spacer (an empty gap column). For example columns = [:ncalls, :time, :time_pct, :time_par]. The :time_min, :time_max and :time_std columns show the fastest and slowest single call and the standard deviation across calls (useful, like @btime's minimum, to gauge run-to-run variation); they are off by default. The _bar columns show each section's share of the total as a bar, colored from blue (cheap) to red (expensive) in color-capable terminals. The :gc_time column shows the time spent in garbage collection within each section
allocations::Bool ─ show the allocation columns (default true); shorthand for a columns selection
compact::Bool ─ hide the avg and bar columns (default false); shorthand for a columns selection
bars::Bool ─ show the bar columns (default true); shorthand for a columns selection
gc::Bool ─ show the GC time column (default false); shorthand for a columns selection
sortby::Symbol ─ sort the sections according to :time (default), :ncalls, :allocations, :name or :firstexec
linechars::Symbol ─ use either :unicode (default) or :ascii for a pure ASCII table
maxdepth::Int ─ only print sections nested up to this depth (default: no limit)
complement::Bool ─ also show what was not timed, in gray: a ~untimed~ row with the wall time and allocations outside all sections, and a ~name~ row under each section with the part not covered by its subsections (default false)
pretty_table_kwargs::NamedTuple ─ escape hatch forwarded verbatim to PrettyTables.pretty_table and splatted last, so it overrides anything TimerOutputs sets (default (;)). For example, the whole table is printed no matter the terminal height; (; fit_table_in_display_vertically = true) crops it to the display instead. Note that these keywords belong to PrettyTables, not to TimerOutputs, and are therefore not covered by TimerOutputs' semantic versioning ─ they may change when the PrettyTables compat bound is raised.

Flattening

If sections are nested like in the example below:

to = TimerOutput()

@timeit to "nest 1" begin
    sleep(0.1)
    @timeit to "level 2.1" sleep(0.1)
    for i in 1:20; @timeit to "level 2.2" sleep(0.02); end
end
@timeit to "nest 2" begin
    for i in 1:30; @timeit to "level 2.1" sleep(0.01); end
    @timeit to "level 2.2" sleep(0.1)
end

the table is displayed as:

julia> show(to, allocations = false, compact = true)
──────────────────────────────────────
 Section       ncalls    time    %tot
──────────────────────────────────────
 nest 1             1   632ms   58.9%
 ├─ level 2.2      20   427ms   39.8%
 └─ level 2.1       1   101ms    9.4%
 nest 2             1   441ms   41.1%
 ├─ level 2.1      30   339ms   31.6%
 └─ level 2.2       1   101ms    9.4%
──────────────────────────────────────

It is possible to flatten this timer using the TimerOutputs.flatten function that accumulates the data for all sections with identical labels:

julia> to_flatten = TimerOutputs.flatten(to);

julia> show(to_flatten; compact = true, allocations = false)
───────────────────────────────────
 Section    ncalls    time    %tot
───────────────────────────────────
 nest 1          1   632ms   58.9%
 level 2.2      21   528ms   49.2%
 nest 2          1   441ms   41.1%
 level 2.1      31   440ms   41.0%
───────────────────────────────────

Merging

Two or more timers can be merged using merge or merge!:

julia> to1 = TimerOutput(); to2 = TimerOutput();

julia> @timeit to1 "outer" begin
           @timeit to1 "inner" begin
                sleep(1)
           end
       end

julia> @timeit to2 "outer" begin
           sleep(1)
       end

julia> show(to1; compact=true, allocations=false)
──────────────────────────────────
 Section   ncalls    time    %tot
──────────────────────────────────
 outer          1   1.00s  100.0%
 └─ inner       1   1.00s  100.0%
──────────────────────────────────

julia> show(to2; compact=true, allocations=false)
─────────────────────────────────
 Section  ncalls    time    %tot
─────────────────────────────────
 outer         1   1.00s  100.0%
─────────────────────────────────

julia> show(merge(to1, to2); compact=true, allocations=false)
──────────────────────────────────
 Section   ncalls    time    %tot
──────────────────────────────────
 outer          2   2.01s  100.0%
 └─ inner       1   1.00s   50.1%
──────────────────────────────────

Merging can be used to facilitate timing coverage throughout simple multi-threaded setups. For instance, use thread-local TimerOutput objects that are merged at custom merge points via the tree_point keyword arg, which is a vector of label strings used to navigate to the merge point in the timing tree. merge! is thread-safe via a lock.

julia> using TimerOutputs

julia> to = TimerOutput()

julia> @timeit to "1" begin
    @timeit to "1.1" sleep(0.1)
    @timeit to "1.2" sleep(0.1)
    @timeit to "1.3" sleep(0.1)
end

julia> @timeit to "2" Threads.@spawn begin
    to2 = TimerOutput()
    @timeit to2 "2.1" sleep(0.1)
    @timeit to2 "2.2" sleep(0.1)
    @timeit to2 "2.3" sleep(0.1)
    merge!(to, to2, tree_point = ["2"])
end

julia> to
 ──────────────────────────────────────────────────────────────────
                           Time                   Allocations
                   ──────────────────────   ───────────────────────
 Tot / % measured:      3.23s / 9.79%           13.5MiB / 36.9%
 Section   ncalls     time   %tot     avg     alloc   %tot      avg
 ──────────────────────────────────────────────────────────────────
 1              1    309ms  98.0%   309ms   4.55MiB  91.5%  4.55MiB
   1.3          1    106ms  33.6%   106ms      320B  0.01%     320B
   1.2          1    102ms  32.3%   102ms      320B  0.01%     320B
   1.1          1    101ms  32.0%   101ms   4.54MiB  91.4%  4.54MiB
 2              1   6.47ms  2.05%  6.47ms    435KiB  8.54%   435KiB
   2.2          1    106ms  33.6%   106ms      480B  0.01%     480B
   2.3          1    105ms  33.4%   105ms      144B  0.00%     144B
   2.1          1    103ms  32.5%   103ms   5.03MiB  101%   5.03MiB
 ──────────────────────────────────────────────────────────────────

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.

Indexing into a table

Any TimerOutput can be indexed with the name of a section which returns a new TimerOutput with that section as the "root". For example:

to = TimerOutput()

@timeit to "nest 1" begin
    @timeit to "nest 2" begin
        @timeit to "nest 3.1" sleep(0.1)
        @timeit to "nest 3.2" sleep(0.1)
        @timeit to "nest 3.3" sleep(0.1)
    end
    sleep(0.3)
end

julia> show(to; compact = true, allocations = false, linechars = :ascii)
 -------------------------------------
 Section        ncalls     time   %tot
 -------------------------------------
 nest 1              1    605ms   100%
   nest 2            1    304ms  50.2%
     nest 3.2        1    101ms  16.7%
     nest 3.1        1    101ms  16.7%
     nest 3.3        1    101ms  16.7%
 -------------------------------------

julia> to_2 = to["nest 1"]["nest 2"];

julia> show(to_2; compact = true, allocations = false, linechars = :ascii)
 ---------------------------------
 Section    ncalls     time   %tot
 ---------------------------------
 nest 3.2        1    101ms  33.3%
 nest 3.1        1    101ms  33.3%
 nest 3.3        1    101ms  33.3%
 ---------------------------------

The percentages showed are now relative to that "root".

Timing in multithreaded / concurrent code

A TimerOutput must only be used from one task at a time — timing sections on the same instance concurrently from multiple threads or tasks will race. Instead, use one TimerOutput per task and combine them with merge! at a join point (which is protected by a lock), as shown in the section on merging above.

Querying data

The (unexported) functions ncalls, time, allocated give the accumulated data for a section. The returned time has units in nano seconds and allocations in bytes. For example (using the to object from above):

julia> TimerOutputs.ncalls(to["nest 1"])
1

julia> TimerOutputs.time(to["nest 1"]["nest 2"])
350441733

julia> TimerOutputs.allocated(to["nest 1"]["nest 2"])
5280

Furthermore, you can request the total time spent in the "root" timer:

julia> TimerOutputs.tottime(to)
604937208

julia> TimerOutputs.totallocated(to)
7632

Default Timer

It is often the case that it is enough to only use one timer. For convenience, there is therefore a version of all the functions and macros that do not take a TimerOutput instance and then use a global timer defined in the package. Note that this global timer is shared among all users of the package. For example:

reset_timer!()

@timeit "section" sleep(0.02)
@timeit "section2" sleep(0.1)

print_timer()

which prints:

julia> print_timer()
────────────────────────────────────────────────────────────────────────
                              Time                   Allocations
                     ──────────────────────    ────────────────────────
 Tot / % measured:       152ms / 80.4%              1.50MiB / 0.1%
 ──────────────────  ──────────────────────    ────────────────────────
 Section     ncalls    time    %tot     avg      alloc    %tot      avg
────────────────────────────────────────────────────────────────────────
 section2         1   101ms   82.7%   101ms       400B   50.0%     400B
 section          1  21.2ms   17.3%  21.2ms       400B   50.0%     400B
────────────────────────────────────────────────────────────────────────

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 easiest way to see this is the complement = true display option, which adds (without modifying the timer) gray rows for everything that was not timed: a ~untimed~ row with the wall time and allocations outside all sections, and a ~name~ row under each section with the part not covered by its subsections:

julia> print_timer(to; complement = true)
──────────────────────────────────────────────────────────────────────────
                                Time                   Allocations
                       ──────────────────────    ────────────────────────
  Tot / % measured:        126ms / 50.4%              1.18MiB / 0.1%
 ────────────────────  ──────────────────────    ────────────────────────
 Section       ncalls    time    %tot     avg      alloc    %tot      avg
──────────────────────────────────────────────────────────────────────────
 ~untimed~             62.4ms                    1.18MiB
 compute            1  52.2ms   82.4%  52.2ms    1.39KiB   78.1%  1.39KiB
 ├─ kernel          1  31.1ms   49.2%  31.1ms       400B   21.9%     400B
 └─ ~compute~       1  21.1ms   33.3%  21.1ms    1.00KiB   56.1%  1.00KiB
 io                 1  11.1ms   17.6%  11.1ms       400B   21.9%     400B
──────────────────────────────────────────────────────────────────────────

Alternatively, the TimerOutputs.complement! function can be used to modify a timer in place and add the complement values as real sections. For instance:

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> print_timer(to)
───────────────────────────────────────────────────────────────────────────
                                 Time                   Allocations
                        ──────────────────────    ────────────────────────
   Tot / % measured:        140ms / 97.2%              265KiB / 2.1%
 ─────────────────────  ──────────────────────    ────────────────────────
 Section        ncalls    time    %tot     avg      alloc    %tot      avg
───────────────────────────────────────────────────────────────────────────
 section2            1   112ms   82.5%   112ms    1.39KiB   24.9%  1.39KiB
 ├─ section2.1       1   101ms   74.3%   101ms       400B    7.0%     400B
 └─ ~section2~       1  11.1ms    8.2%  11.1ms    1.00KiB   17.9%  1.00KiB
 section1            1  23.9ms   17.5%  23.9ms    4.19KiB   75.1%  4.19KiB
───────────────────────────────────────────────────────────────────────────

In order to complement the default timer simply call TimerOutputs.complement!().

Shared Timers

It is sometimes desirable for a timer to be shared across all users of the package. For this purpose, get_timer maintains a collection of named timers defined in the package.

get_timer(timer_name::String) retrieves the timer timer_name from the collection, creating a new timer if none already exists.

For example:

module UseTimer
using TimerOutputs: @timeit, get_timer

function foo()
    to = get_timer("Shared")
    @timeit get_timer("Shared") "foo" sleep(0.1)
end
end

@timeit get_timer("Shared") "section1" begin
    UseTimer.foo()
    sleep(0.01)
end

which prints:

julia> print_timer(get_timer("Shared"))
────────────────────────────────────────────────────────────────────────
                              Time                   Allocations
                     ──────────────────────    ────────────────────────
 Tot / % measured:       124ms / 99.9%             1.30MiB / 99.6%
 ──────────────────  ──────────────────────    ────────────────────────
 Section     ncalls    time    %tot     avg      alloc    %tot      avg
────────────────────────────────────────────────────────────────────────
 section1         1   124ms  100.0%   124ms    1.30MiB  100.0%  1.30MiB
 └─ foo           1   101ms   81.6%   101ms       224B    0.0%     224B
────────────────────────────────────────────────────────────────────────

Note that the result of get_timer should not be called from top-level in a package that is getting precompiled since the retrieved timer will no longer be shared with other users getting a timer with the same name. Also, this function is not recommended to be used extensively by libraries as the namespace is shared and collisions are possible if two libraries happen to use the same timer name.

Tables.jl integration

Timers implement the Tables.jl interface: one row per section in depth-first order, with the raw (unformatted) measurements. This means they can be passed directly to any Tables-consuming package, e.g. DataFrame(to) or CSV.write("timings.csv", to):

julia> Tables.columntable(to)
(path = ["nest 1", "nest 1/level 2.1", "nest 1/level 2.2", "nest 2", ...],
 section = ["nest 1", "level 2.1", "level 2.2", "nest 2", ...],
 depth = [0, 1, 1, 0, ...],
 ncalls = [1, 1, 20, 1, ...],
 time_ns = [625648679, 100547624, 422780218, 435925439, ...],
 gc_time_ns = [0, 0, 0, 0, ...],
 allocated_bytes = [1392, 112, 2240, 944, ...],
 firstexec_ns = [40605122592791, 40605223345650, 40605324068660, ...])

The path column joins the nesting with / for readability; depth together with the row order reconstructs the tree exactly.

Serialization

Timers may be converted to a nested set of dictionaries with the (unexported) TimerOutputs.todict function. This can be used to serialize a timer as JSON, for example.

julia> to = TimerOutput();

julia> @timeit to "nest 1" begin
           sleep(0.1)
           @timeit to "level 2.1" sleep(0.1)
           for i in 1:20; @timeit to "level 2.2" sleep(0.02); end
       end

julia> TimerOutputs.todict(to)
Dict{String, Any} with 7 entries:
  "total_time_ns" => 726721166
  "total_allocated_bytes" => 474662
  "time_ns" => 0
  "n_calls" => 0
  "gc_time_ns" => 0
  "allocated_bytes" => 0
  "inner_timers" => Dict{String, Any}("nest 1"=>Dict{String, Any}("total_time_ns"=>611383374, "total_allocated_bytes"=>11888, "time_ns"=>726721166, "n_calls"=>1, "gc_time_ns"=>0, "allocated_bytes"=>474662, "inner_timers"=>Dict{String, Any}("level 2.1"=>Dict{String, Any}("total_time_ns"=>0, "total_allocated_bytes"=>0, "time_ns"=>115773750, "n_calls"=>1, "gc_time_ns"=>0, "allocated_bytes"=>8064, "inner_timers"=>Dict{String, Any}()), "level 2.2"=>Dict{String, Any}("total_time_ns"=>0, "total_allocated_bytes"=>0, "time_ns"=>495609624, "n_calls"=>20, "gc_time_ns"=>0, "allocated_bytes"=>3824, "inner_timers"=>Dict{String, Any}()))))

julia> using JSON3 # or JSON

julia> JSON3.write(TimerOutputs.todict(to))
"{\"total_time_ns\":712143250,\"total_allocated_bytes\":5680,\"time_ns\":0,\"n_calls\":0,\"gc_time_ns\":0,\"allocated_bytes\":0,\"inner_timers\":{\"nest 1\":{\"total_time_ns\":605922416,\"total_allocated_bytes\":4000,\"time_ns\":712143250,\"n_calls\":1,\"gc_time_ns\":0,\"allocated_bytes\":5680,\"inner_timers\":{\"level 2.1\":{\"total_time_ns\":0,\"total_allocated_bytes\":0,\"time_ns\":106111333,\"n_calls\":1,\"gc_time_ns\":0,\"allocated_bytes\":176,\"inner_timers\":{}},\"level 2.2\":{\"total_time_ns\":0,\"total_allocated_bytes\":0,\"time_ns\":499811083,\"n_calls\":20,\"gc_time_ns\":0,\"allocated_bytes\":3824,\"inner_timers\":{}}}}}}"

FlameGraphs

TimerOutputs has a FlameGraph extension that provides an alternative visualization method.

i.e. using ProfileView.jl

using TimerOutputs, FlameGraphs, ProfileView
to = TimerOutput()
@timeit to "foo" begin
    sleep(0.1)
    @timeit to "bar" begin
        sleep(0.1)
        @timeit to "baz" begin
            sleep(0.1)
        end
    end
end
ProfileView.view(flamegraph(to))

You may want to crop the span of the graph to the children, not how long to has been open. To do that use crop_root=true

ProfileView.view(flamegraph(to, crop_root=true))

Overhead

There is a small overhead in timing a section (~30 ns on a modern machine, dominated by reading the clock) which means that this package is not suitable for measuring sections that finish very quickly. For proper benchmarking you want to use a more suitable tool like BenchmarkTools.

It is sometimes desireable to be able "turn on and off" the @timeit macro, for instance you may wish to instrument a package with @timeit macros, but then not deal with the overhead of the timings during normal package operation. To enable this, we provide the @timeit_debug macro, which wraps the @timeit macro with a conditional, checking if debug timings have been enabled. Because you may wish to turn on only certain portions of your instrumented code base (or multiple codebases may have instrumented their code), debug timings are enabled on a module-by-module basis. By default, debug timings are disabled, and this conditional should be optimized away, allowing for truly zero-overhead. If a user calls TimerOutputs.enable_debug_timings(<module>), the <module>.timeit_debug_enabled() method will be redefined, causing all dependent methods to be recompiled within that module. This may take a while, and hence is intended only for debugging usage, however all calls to @timeit_debug (within that Module) will thereafter be enabled. By default this recurses into submodules, so a single call on a package's top module instruments the whole package; pass recursive = false to affect only the given module. TimerOutputs.disable_debug_timings(<module>) turns them back off (also recursive by default).

An alternative zero-overhead mechanism is NoTimerOutput: a dummy timer where every timing operation is a no-op. When the type of the timer is known to the compiler — a const, or a type parameter of the struct it is stored in — the timed sections compile away entirely:

struct Solver{Timer}
    to::Timer
end

solve(s::Solver) = @timeit s.to "solve" begin ... end

Solver(TimerOutput())   # timed
Solver(NoTimerOutput()) # timing compiled away

Unlike @timeit_debug, this selects timing per timer object instead of per module and involves no recompilation trickery, but flipping it requires reconstructing the object that holds the timer.

Author

Kristoffer Carlsson - @KristofferC

Acknowledgments

This package is inspired by the TimerOutput class in deal.ii.

Name		Name	Last commit message	Last commit date
.github/workflows		.github/workflows
.quality-env		.quality-env
ext/FlameGraphsExt		ext/FlameGraphsExt
src		src
test		test
.gitignore		.gitignore
.pre-commit-config.yaml		.pre-commit-config.yaml
CHANGELOG.md		CHANGELOG.md
LICENSE.md		LICENSE.md
Project.toml		Project.toml
README.md		README.md

Navigation Menu

Repository files navigation

TimerOutputs

Example output

Usage

Timing test sets

Settings for printing:

Flattening

Merging

Resetting

Indexing into a table

Timing in multithreaded / concurrent code

Querying data

Default Timer

Measuring time consumed outside `@timeit` blocks

Shared Timers

Tables.jl integration

Serialization

FlameGraphs

Overhead

Author

Acknowledgments

About

Releases

Packages

Used by

Contributors

Languages

Latest commit

History

Folders and files

Repository files navigation

TimerOutputs

Example output

Usage

Timing test sets

Settings for printing:

Flattening

Merging

Resetting

Indexing into a table

Timing in multithreaded / concurrent code

Querying data

Default Timer

Measuring time consumed outside @timeit blocks

Shared Timers

Tables.jl integration

Serialization

FlameGraphs

Overhead

Author

Acknowledgments

About

Resources

Stars

Watchers

Forks

Releases

Packages

Used by

Contributors

Languages

Measuring time consumed outside `@timeit` blocks