Timing

With TimerOutputs.jl loaded, enable_cache_timers! records the time spent in the cached functions of a package, in sections per function:

• lookup f wraps the whole cache lookup, hit or miss;
• compute f wraps the call of the implementation: nested in lookup f on a miss, and on its own under NoCache;
• disk f, for functions with a disk cache, wraps the disk lookup after a RAM miss, with compute f nested in it when the disk misses too.

using MemoizationKit, TimerOutputs

@cached weights(a, b, c) = a + b * c
@cached matrix(n::Int)::Matrix{Float64} = zeros(n, n)

to = TimerOutput()
enable_cache_timers!(@__MODULE__, to)   # the timer defaults to TimerOutputs' global one
for i in 1:200
    weights(1 + i % 6, 1 + (7i) % 6, 1 + (13i) % 6)
    matrix(1 + i % 10)
end
disable_cache_timers!(@__MODULE__)
to

────────────────────────────────────────────────────────────────────────────────
                                   Time                        Allocations     ⋯
                     ────────────────────────────────    ───────────────────────
 Tot / % measured:             1.47s / 2.5%                   83.9MiB / 0.8%   ⋯
 ──────────────────  ────────────────────────────────    ───────────────────────
 Section     ncalls    time    %tot     avg                alloc    %tot       ⋯
────────────────────────────────────────────────────────────────────────────────
 lookup ma…     200  23.3ms   63.6%   116μs  █████▏       473KiB   66.2%  2.36 ⋯
 └─ comput…      10  2.84μs    0.0%   284ns              3.86KiB    0.5%     3 ⋯
 lookup we…     200  13.3ms   36.4%  66.6μs  ██▉          242KiB   33.8%  1.21 ⋯
 └─ comput…       6   290ns    0.0%  48.3ns                    ∅       ∅       ⋯
────────────────────────────────────────────────────────────────────────────────
                                                               2 columns omitted

Timing is off by default and adds no overhead while off. Enabling or disabling it recompiles callers and takes effect from the next top-level statement. If a function enables timers and calls cached functions in the same invocation, use invokelatest for those calls. Enabling a package again replaces its timer. Do not enable timers during precompilation.

What counts is the package that owns the function (including its submodules), not where @cached was written; modules outside packages, such as in the REPL, count separately. For instance, if MyPackage adds @cached methods to a function OtherPackage.f, then enable_cache_timers!(OtherPackage) times them, and enable_cache_timers!(MyPackage) does not. A package that wants all of its cached functions timed enables the packages that own them:

function MyPackage.enable_timers!()
    enable_cache_timers!(MyPackage, TIMER)
    enable_cache_timers!(OtherPackage, TIMER)
end

MyPackage.enable_timers!()
OtherPackage.f(2)
disable_cache_timers!(MyPackage)
disable_cache_timers!(OtherPackage)
TIMER

────────────────────────────────────────────────────────────────────────────────
                                   Time                        Allocations     ⋯
                     ────────────────────────────────    ───────────────────────
 Tot / % measured:            92.5ms / 14.5%                  10.1MiB / 2.3%   ⋯
 ──────────────────  ────────────────────────────────    ───────────────────────
 Section     ncalls    time    %tot     avg                alloc    %tot       ⋯
────────────────────────────────────────────────────────────────────────────────
 lookup f         1  13.4ms  100.0%  13.4ms  ████████     240KiB  100.0%   240 ⋯
 └─ comput…       1   290ns    0.0%   290ns                    ∅       ∅       ⋯
────────────────────────────────────────────────────────────────────────────────
                                                               2 columns omitted

The labels come from MemoizationKit.instrument_label, "lookup f" and "compute f" by default; overload it to pick your own:

MemoizationKit.instrument_label(::typeof(weights), ::Val{:lookup}) = "cache: weights"
MemoizationKit.instrument_label(weights, Val(:lookup))

"cache: weights"