Overhead

Timing a section costs about one microsecond on a modern machine: entering and exiting a with TimerContext(...) block, or calling a decorated function. That’s negligible for sections that take milliseconds or more. For code that runs millions of times in a tight loop, time the loop rather than each iteration, or reuse one context.

A few habits keep the cost down:

  • Reuse contexts in hot loops. Creating a TimerContext each time is slightly slower than entering an existing one. Decorators already reuse theirs.

  • Keep reporting out of hot paths. Reports copy the registry under its lock, and the JSON export also orders and serializes every section. Read the timings when you need them, not on every iteration.

  • Leave log_execution_times() in place. It returns immediately, without building a report, when its logger has INFO disabled.

Measuring it yourself

The repository includes a benchmark for recording and reporting costs. From a checkout:

uv run python benchmarks/overhead.py --number 100000 --repeat 9

It prints the median nanoseconds per operation as JSON. Compare results on the same interpreter and machine, without coverage or a profiler running. See benchmarks/README.md for the methodology.

Reference results

Measured on macOS 26.6.2, ARM64, CPython 3.14.5, using 100,000 operations and nine repeats. The baseline is commit 008494c (version 0.1.0). All three versions ran the same script, one after the other. Values below are microseconds per operation and include the benchmark function call; plain calls cost approximately 0.02 µs and plain awaits 0.06 µs in every run. The last column compares 1.0.3 with the baseline.

Operation

0.1.0 (µs)

1.0.2 (µs)

1.0.3 (µs)

Reduction

New context

1.604

1.116

0.877

45%

Reused context

1.433

1.013

0.786

45%

Decorated call

1.656

1.220

0.897

46%

Decorated await

1.800

1.197

0.948

47%

Five nested contexts

8.238

5.782

4.371

47%

Total time, 1,000 sections

522.668

43.786

43.630

92%

JSON, 1,000 sections

1,255.098

1,139.416

1,065.708

15%

Disabled logging, 1,000 sections

530.408

0.100

0.100

>99.9%

Recording keeps each invocation’s start time and cached path in a context-local frame, stored as a plain tuple because a named tuple’s constructor costs more than the rest of entering a section. Decorators reuse their context instead of constructing one per call. Total-time queries avoid copying and flattening entries, JSON exports share one snapshot, and disabled logging returns before building a report.