TrackingTimers
Provides a simple utility for collecting timing information from functions even in the presence of parallelism. Inspired by TimerOutputs.jl, which I recommend for serial code.
TrackingTimers.@timeit supports the same API as TimerOutputs.@timeit, providing a simple way to store the timing results from executing an expression in a timer object, a TrackingTimer (which is the sole export of this package). However, TrackingTimers are very simple; while calls to log to the same timer may be nested, the TrackingTimer simply logs each call in a flat table. This makes it easy to support multiprocess and multithreaded code. TrackingTimers supports the Tables.jl interface (as a row table), which provides a simple means for the user to take a closer look at the timing data, and e.g. aggregate over calls to the same function.
TrackingTimers also support a call syntax, allowing one to easily instrument a function, so that any call to the instrumented version of the function automatically logs a timing entry to the timer object. See the examples below.
Usage
julia> using TrackingTimers
julia> t = TrackingTimer()
TrackingTimer: 0.00 s since creation (0% measured).
No entries.
julia> TrackingTimers.@timeit t "testing: sleep" sleep(1)
julia> t
TrackingTimer: 1.05 s since creation (96% measured).
name time gctime n_allocs allocs thread ID proc ID
─────────────────────────────────────────────────────────────────────────
testing: sleep 1.00 s 0% 4 128 bytes 1 1
julia> func(x) = x+1
func (generic function with 1 method)
julia> func_inst = t(func)
(::TrackingTimers.InstrumentedFunction{typeof(func)}) (generic function with 1 method)
julia> func_inst(5)
6
julia> t
TrackingTimer: 1.08 s since creation (93% measured).
name time gctime n_allocs allocs thread ID proc ID
─────────────────────────────────────────────────────────────────────────
testing: sleep 1.00 s 0% 4 128 bytes 1 1
func 0.00 s 0% 0 0 bytes 1 1Threaded example
julia> using TrackingTimers, ThreadsX, LinearAlgebra
julia> t = TrackingTimer()
TrackingTimer: 0.03 s since creation (0% measured).
No entries.
julia> xs = 1:2
1:2
julia> expensive_function(i) = norm(big.(randn(i, i)))
expensive_function (generic function with 1 method)
julia> instrumented_fun = t(expensive_function)
(::TrackingTimers.InstrumentedFunction{typeof(expensive_function)}) (generic function with 1 method)
julia> result = ThreadsX.map(instrumented_fun, 1000:100:1500)
6-element Vector{BigFloat}:
1000.044535870264540807714716029272380072359744688303289140287700941397780730317
1099.621613467886456092200351321349092989369319781554075855193975305734925337306
1200.160425251366463083085189603332616730336307297852815966102953629237891121993
1300.109241847853807385664372197135060201125417086855868596616484800661239594506
1399.572257779217012297991715825651075215168607390190375753707375897223959998925
1499.967376120230484827902676300684847759014653732263746767025105628459031638143
julia> t
TrackingTimer: 5.69 s since creation (99% measured).
name time gctime n_allocs allocs thread ID proc ID
───────────────────────────────────────────────────────────────────────────────
expensive_function 1.34 s 72% 37334279 1.999 GiB 2 1
expensive_function 1.20 s 39% 31436022 1.702 GiB 1 1
expensive_function 1.15 s 34% 24886121 1.360 GiB 2 1
expensive_function 0.71 s 18% 15721283 880.679 MiB 1 1
expensive_function 0.66 s 36% 18870866 1.024 GiB 1 1
expensive_function 0.58 s 16% 14264890 784.059 MiB 2 1Distributed example
julia> using Distributed
julia> addprocs(2)
2-element Vector{Int64}:
2
3
julia> @everywhere using TrackingTimers, LinearAlgebra
julia> t = TrackingTimer()
TrackingTimer: 1.13 s since creation (0% measured).
No entries.
julia> @everywhere expensive_function(i) = norm(big.(randn(i, i)))
julia> instrumented_fun = t(expensive_function)
(::TrackingTimers.InstrumentedFunction{typeof(expensive_function)}) (generic function with 1 method)
julia> result = pmap(instrumented_fun, 1000:100:1500)
6-element Vector{BigFloat}:
999.3400434505995581074342593748743616158636434344468541490681472178697961023743
1099.00165758571901999414118783850318868603547862200331037349314999751473860877
1200.665671521870570295977221776311554666404776867075257827116985832523690068542
1299.098003099051425268090436142914593167431536776385646086568449446658084891494
1400.026473159472270359947791624394367075116800578307064157908754557301584756459
1498.256323158788435294406273058988870732250411479016050182811541955477979434318
julia> t
TrackingTimer: 5.70 s since creation (93% measured).
name time gctime n_allocs allocs thread ID proc ID
───────────────────────────────────────────────────────────────────────────────
expensive_function 1.35 s 69% 18000012 995.637 MiB 1 2
expensive_function 1.11 s 49% 15680012 867.310 MiB 1 3
expensive_function 1.00 s 31% 13520012 747.834 MiB 1 2
expensive_function 0.75 s 14% 11520012 637.208 MiB 1 3
expensive_function 0.70 s 18% 9680012 535.431 MiB 1 3
expensive_function 0.61 s 13% 8000012 442.505 MiB 1 2Table interface
Continuing the previous example, we can use the fact that TimingTracker's support the Tables.jl interface to do further analysis of the results.
julia> cheap_fn(x) = x+1
cheap_fn (generic function with 1 method)
julia> map(t(cheap_fn), 10:15)
6-element Vector{Int64}:
11
12
13
14
15
16
julia> using DataFrames, Statistics
julia> df = DataFrame(t)
12×7 DataFrame
Row │ name time gctime n_allocs bytes thread_id pid
│ String Float64 Float64 Int64 Int64 Int64 Int64
─────┼────────────────────────────────────────────────────────────────────────────────
1 │ expensive_function 0.612077 0.176828 8000012 464000560 1 2
2 │ expensive_function 0.701691 0.200751 9680012 561440560 1 3
3 │ expensive_function 0.748993 0.139915 11520012 668160560 1 3
4 │ expensive_function 0.99935 0.234239 13520012 784160560 1 2
5 │ expensive_function 1.11177 0.343141 15680012 909440560 1 3
6 │ expensive_function 1.34677 0.422423 18000012 1044000560 1 2
7 │ cheap_fn 1.67e-7 0.0 0 0 1 1
8 │ cheap_fn 4.1e-8 0.0 0 0 1 1
9 │ cheap_fn 0.0 0.0 0 0 1 1
10 │ cheap_fn 4.1e-8 0.0 0 0 1 1
11 │ cheap_fn 0.0 0.0 0 0 1 1
12 │ cheap_fn 4.2e-8 0.0 0 0 1 1
julia> combine(groupby(df, :name), :time => mean)
2×2 DataFrame
Row │ name time_mean
│ String Float64
─────┼───────────────────────────────
1 │ expensive_function 0.920108
2 │ cheap_fn 4.85e-8Similarly, the timing results can be serialized by e.g. CSV.write(path, t) or Arrow.write(path, t), thanks again to the Tables.jl interface.