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)