From de1286a226b01d15870e6d1e1e6ac127d2ff4a55 Mon Sep 17 00:00:00 2001 From: Sebastian Yde Madsen <75695915+seba2390@users.noreply.github.com> Date: Wed, 30 Sep 2026 23:47:10 +0200 Subject: [PATCH] Release 1.0.3: store active-section frames as plain tuples Constructing the _Frame NamedTuple ran a Python-level __new__ that cost about 190 ns, more than the rest of section entry combined. A plain tuple costs about 30 ns, making entering and exiting a section 20-25% faster across 3.11, 3.14 and free-threaded 3.14t. Behaviour is unchanged. Also refresh the overhead benchmark with 0.1.0, 1.0.2 and 1.0.3 measured back to back, and release the documentation site changes, so the PyPI page gets the shorter README and the Documentation link. --- CHANGELOG.md | 15 ++++++++++-- benchmarks/README.md | 41 +++++++++++++++++---------------- src/execution_timer/__init__.py | 2 +- src/execution_timer/_timer.py | 33 ++++++++++++-------------- 4 files changed, 50 insertions(+), 41 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 54c9787..43e40f9 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,17 +7,27 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +## [1.0.3] - 2026-09-30 + +### Changed + +- Entering and exiting a section is 20–25% faster, about 0.25 µs less per section on + CPython 3.14. Each active section's state is now a plain tuple rather than a named + tuple, whose constructor cost more than the rest of section entry. Behaviour is + unchanged. + ### Documentation - A documentation site at , with a getting started guide, a user guide and an API reference generated from the docstrings. It is built with Sphinx and deployed to GitHub Pages whenever `main` changes. The package's - `Documentation` link points to it from the next release on. + `Documentation` link points to it from this release on. - The README is shorter and links to the site for details. - Public functions and types have full docstrings, with parameters, return values and exceptions. - The Python examples in the README and the documentation run as part of the test suite, and CI builds the site on every pull request, failing on any warning. +- Refresh the overhead benchmark, comparing 0.1.0, 1.0.2 and 1.0.3. ## [1.0.2] - 2026-09-30 @@ -184,7 +194,8 @@ First public release on PyPI. `py.typed` marker so type checkers use the inline annotations. - `__version__` attribute on the package. -[Unreleased]: https://github.com/seba2390/ExecutionTimer/compare/v1.0.2...HEAD +[Unreleased]: https://github.com/seba2390/ExecutionTimer/compare/v1.0.3...HEAD +[1.0.3]: https://github.com/seba2390/ExecutionTimer/compare/v1.0.2...v1.0.3 [1.0.2]: https://github.com/seba2390/ExecutionTimer/compare/v1.0.1...v1.0.2 [1.0.1]: https://github.com/seba2390/ExecutionTimer/compare/v1.0.0...v1.0.1 [1.0.0]: https://github.com/seba2390/ExecutionTimer/compare/v0.2.0...v1.0.0 diff --git a/benchmarks/README.md b/benchmarks/README.md index 8dce562..2ca191c 100644 --- a/benchmarks/README.md +++ b/benchmarks/README.md @@ -18,23 +18,24 @@ make instrumentation costs visible; application speedups depend on the work bein ## Local comparison 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); the updated column is version 1.0.2. -Both 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 both runs. - -| Operation | Baseline (µs) | Updated (µs) | Reduction | -| --- | ---: | ---: | ---: | -| New context | 1.558 | 1.101 | 29% | -| Reused context | 1.390 | 1.039 | 25% | -| Decorated call | 1.623 | 1.129 | 30% | -| Decorated await | 1.711 | 1.133 | 34% | -| Five nested contexts | 7.961 | 5.380 | 32% | -| Total time, 1,000 sections | 519.131 | 43.188 | 92% | -| JSON, 1,000 sections | 1,235.188 | 1,064.559 | 14% | -| Disabled logging, 1,000 sections | 572.003 | 0.098 | >99.9% | - -Recording keeps each invocation's start time and cached path in a context-local frame. -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. +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. diff --git a/src/execution_timer/__init__.py b/src/execution_timer/__init__.py index 5426643..e779e34 100644 --- a/src/execution_timer/__init__.py +++ b/src/execution_timer/__init__.py @@ -18,7 +18,7 @@ save_execution_timings_json, ) -__version__ = "1.0.2" +__version__ = "1.0.3" __all__ = [ "DEFAULT_CATEGORY", diff --git a/src/execution_timer/_timer.py b/src/execution_timer/_timer.py index b7c3f88..7894dd6 100644 --- a/src/execution_timer/_timer.py +++ b/src/execution_timer/_timer.py @@ -20,7 +20,7 @@ from itertools import count from pathlib import Path from types import TracebackType -from typing import Final, NamedTuple, ParamSpec, TypedDict, TypeVar, cast +from typing import Final, ParamSpec, TypeAlias, TypedDict, TypeVar, cast P = ParamSpec("P") R = TypeVar("R") @@ -71,14 +71,10 @@ class _TimesDict(TypedDict): category: str -class _Frame(NamedTuple): - """Per-invocation state, with a cached path and an immutable parent link.""" - - path: tuple[str, ...] - category: str - start_time: float - entry: _TimesDict - parent: _Frame | None +# Per-invocation state, with a cached path and an immutable parent link: +# ``(path, category, start_time, entry, parent)``. A plain tuple rather than a NamedTuple, +# whose constructor runs in Python and costs more than the rest of section entry combined. +_Frame: TypeAlias = "tuple[tuple[str, ...], str, float, _TimesDict, _Frame | None]" _ACTIVE_CONTEXT: ContextVar[_Frame | None] = ContextVar("execution_timer_context", default=None) @@ -143,10 +139,10 @@ def snapshot(self) -> dict[tuple[str, ...], _TimesDict]: def start_timer(self, name: str, category: str) -> None: """Start timing a section under the given name within the active context.""" parent = _ACTIVE_CONTEXT.get() - full_name = (*parent.path, name) if parent is not None else (name,) + full_name = (*parent[0], name) if parent is not None else (name,) with self._lock: - if parent is not None and (parent.category, category) in self.forbidden_nesting: - msg = f"Category '{category}' is not allowed inside category '{parent.category}'." + if parent is not None and (parent[1], category) in self.forbidden_nesting: + msg = f"Category '{category}' is not allowed inside category '{parent[1]}'." raise ValueError(msg) sequence = next(self._sequence) entry: _TimesDict | None = self.timings.get(full_name) @@ -156,7 +152,7 @@ def start_timer(self, name: str, category: str) -> None: else: entry["sequence"] = sequence entry["category"] = category - _ = _ACTIVE_CONTEXT.set(_Frame(full_name, category, time.perf_counter(), entry, parent)) + _ = _ACTIVE_CONTEXT.set((full_name, category, time.perf_counter(), entry, parent)) def stop_timer(self, name: str) -> None: """Stop timing a section and accumulate its elapsed time. @@ -171,19 +167,20 @@ def stop_timer(self, name: str) -> None: end_time = time.perf_counter() active = _ACTIVE_CONTEXT.get() frame = active - while frame is not None and frame.path[-1] != name: - frame = frame.parent + while frame is not None and frame[0][-1] != name: + frame = frame[4] if frame is None: return + _, _, start_time, entry, parent = frame with self._lock: # A clear detaches this entry from the registry. Updating the detached object # cannot resurrect an old sample or add it to a replacement at the same path. - frame.entry["elapsed_time"] += end_time - frame.start_time - _ = _ACTIVE_CONTEXT.set(frame.parent) + entry["elapsed_time"] += end_time - start_time + _ = _ACTIVE_CONTEXT.set(parent) if frame is not active and active is not None: # Warn only once the state is consistent: warnings configured as errors raise here. msg = ( - f"Section '{name}' exited while '{active.path[-1]}' was still active; discarding the " + f"Section '{name}' exited while '{active[0][-1]}' was still active; discarding the " "unfinished inner sections. Close sections before a generator yields." ) warnings.warn(msg, RuntimeWarning, stacklevel=3)