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.83s / 4.2%                   83.4MiB / 1.3%   ⋯
 ──────────────────  ────────────────────────────────    ───────────────────────
 Section     ncalls    time    %tot     avg                alloc    %tot       ⋯
────────────────────────────────────────────────────────────────────────────────
 lookup ma…     200  48.8ms   63.6%   244μs  █████▏       654KiB   60.7%  3.27 ⋯
 └─ comput…      10  3.00μs    0.0%   300ns              3.86KiB    0.4%     3 ⋯
 lookup we…     200  28.0ms   36.4%   140μs  ██▉          423KiB   39.3%  2.11 ⋯
 └─ comput…       6   330ns    0.0%  55.0ns                    ∅       ∅       ⋯
────────────────────────────────────────────────────────────────────────────────
                                                               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:            110ms / 24.8%                   9.92MiB / 4.1%   ⋯
 ──────────────────  ────────────────────────────────    ───────────────────────
 Section     ncalls    time    %tot     avg                alloc    %tot       ⋯
────────────────────────────────────────────────────────────────────────────────
 lookup f         1  27.3ms  100.0%  27.3ms  ████████     422KiB  100.0%   422 ⋯
 └─ comput…       1   181ns    0.0%   181ns                    ∅       ∅       ⋯
────────────────────────────────────────────────────────────────────────────────
                                                               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"