`ic()` spends ~78% of its time in source re-inspection (`_getContext`) - flame graph + numbers for #36

[AhmadAL-Quraan]

Summary

Following up on #36 ("print() is 68 times faster than ic()") with a profiling breakdown of where that time actually goes.

Using py-spy (sampling profiler, 400 Hz) on a simple loop of 8,000 ic() calls, with outputFunction overridden to a no-op so terminal I/O doesn't skew the numbers:

from icecream import ic

ic.configureOutput(outputFunction=lambda s: None)

def foo(i):
    return i + 333

N = 8000
for i in range(N):
    ic(foo(i))

Result: 1,883ms for 8,000 calls (0.235ms/call) → projects to ~2,354ms for 10,000 calls.

Where the time goes

Flame graph (attached: icecream_flame3.svg) shows IceCreamDebugger.__call__ (icecream.py:322) accounting for ~78% of total runtime, almost entirely inside _getContext (icecream.py:458). The top self-time (leaf) functions are:

Function	% of total runtime
inspect._get_code_position (inspect.py:1675)	7.5%
ast.parse (ast.py:52)	6.6%
linecache.checkcache (linecache.py:72)	6.3%
_compile_bytecode (importlib bootstrap)	2.7%
executing.executing (executing/executing.py:221)	1.2%
plus various inspect.getframeinfo, re compilation, asttokens line lookups	~5% combined

So roughly 80% of every ic() call is spent re-parsing and re-inspecting the caller's source file (via inspect + ast + the executing library) to recover the literal expression text not in formatting, pretty-printing, or output.

Why this happens

Each call to _getContext walks the call stack, reads the source file from disk (linecache), and re-parses it with ast.parse to figure out what expression was passed to ic(). This work is identical every time ic() is called from the same call site — the source text and its AST don't change between calls — but it's redone from scratch on every single invocation.

Possible direction (not attempting a PR myself, but flagging for discussion)

A per-call-site cache (keyed on (filename, lineno), and invalidated the same way linecache already invalidates on file changes) could skip the repeated ast.parse + executing walk for calls from the same source location. I haven't attempted this myself since _getContext/executing interaction looks like it needs careful handling of edge cases mentioned elsewhere in the codebase (multiline calls, frozen/REPL contexts, etc.), and I didn't want to hand over an untested change.

Will I lied, I made a PR :))))

Candidate fix

I put together a small, local patch that caches _getContext's result per (code object, lineno, contextAbsPath), since that result is deterministic for a given call site and doesn't need to be recomputed on every call. In my testing this cut the aggregate time roughly a third (numbers above are from the unpatched version; happy to share patched numbers too).

The change is small: one new functools.lru_cache-wrapped helper function, and _getContext's body reduced to a single call into it. Correctness-tested against multiple call sites and against toggling contextAbsPath at runtime (to make sure the cache doesn't return stale paths).

I haven't opened a PR yet since I wanted to check here first whether this is a direction you'd actually want, given your earlier comment that performance isn't a current focus, happy to open one if useful, or happy to just leave this as a data point.

Environment

• icecream 2.2.0 (PyPI)
• Python 3.12.3
• py-spy 0.4.x, sampling at 400 Hz, 8,000 samples of ic() calls

Happy to share the raw .svg / share more detail if useful. Given the maintainer's earlier comment on #36 that "performance is not my focus with IceCream until it presents itself as a problem", posting this mainly as a data point in case it's useful for anyone who does want to pick it up, not pushing for an immediate fix.