From 24e5416a3794525ec953fa26c6cbe5a6ce621ba1 Mon Sep 17 00:00:00 2001 From: Sebastian Yde Madsen <75695915+seba2390@users.noreply.github.com> Date: Wed, 30 Sep 2026 22:30:56 +0200 Subject: [PATCH 1/2] Keep timings consistent after warnings-as-errors and mid-section clears Exiting a section past a still-active inner one emitted its RuntimeWarning before recording the exit. With warnings configured as errors, common under pytest's filterwarnings = ["error"], the warning raised from __exit__, replaced the exception propagating from the timed block, and left the active stack pointing at the abandoned section. The exit is now recorded and the stack unwound before the warning is emitted. Clearing timings while a section is active leaves its children without a recorded parent. The report ordered them as roots but indented them by path length, beneath an unrelated section, and every total counted only single-element paths, so a periodic clear inside an outer section reported a total of 0 and 0.00% for everything. Totals now count every section without a recorded parent, the same roots the hierarchy ordering uses, and the report indents by tree depth. get_total_time, the report and the JSON total share one definition. Recording is untouched and the overhead benchmark is unchanged within noise. --- README.md | 6 ++-- src/execution_timer/_timer.py | 66 ++++++++++++++++++++++------------- tests/execution_timer_test.py | 41 ++++++++++++++++++++-- 3 files changed, 85 insertions(+), 28 deletions(-) diff --git a/README.md b/README.md index fc9f472..ccea686 100644 --- a/README.md +++ b/README.md @@ -229,7 +229,8 @@ time the loop that consumes the generator instead. If the caller's section exits while a paused generator's section is still open, the timer never raises: it emits a `RuntimeWarning`, records the caller's section, and discards the generator's unfinished one, so later sections nest correctly. Closing that -generator afterwards does nothing. +generator afterwards does nothing. If warnings are configured as errors, the warning is +raised only after that cleanup, so the timings and nesting stay consistent. ### Reusing contexts and clearing timings @@ -245,7 +246,8 @@ for item in items: Timings accumulate until `clear_execution_timings()` is called. Clearing also discards samples from sections that were already active, without disturbing their nesting stack. -Sections started after the clear are recorded normally. Reports include completed calls; +Sections started after the clear are recorded normally; if their parent was cleared, they +are reported as top-level sections and count toward the total. Reports include completed calls; an active section's current duration is added only when it exits. ### Measuring overhead diff --git a/src/execution_timer/_timer.py b/src/execution_timer/_timer.py index 829fee3..79fd960 100644 --- a/src/execution_timer/_timer.py +++ b/src/execution_timer/_timer.py @@ -74,11 +74,13 @@ class _Frame(NamedTuple): _ACTIVE_CONTEXT: ContextVar[_Frame | None] = ContextVar("execution_timer_context", default=None) -def _ordered_by_hierarchy(keys: Iterable[tuple[str, ...]]) -> list[tuple[str, ...]]: +def _ordered_by_hierarchy(keys: Iterable[tuple[str, ...]]) -> list[tuple[tuple[str, ...], int]]: """Order section paths depth-first so children always follow their parent. - Insertion order is preserved within each level, so a parent revisited after an unrelated - sibling still renders with its own children rather than beneath the sibling. + Returns each path with its depth in the recorded tree, which is shallower than the path + length when an ancestor is missing. Insertion order is preserved within each level, so a + parent revisited after an unrelated sibling still renders with its own children rather + than beneath the sibling. """ keys = list(keys) known = set(keys) @@ -92,16 +94,28 @@ def _ordered_by_hierarchy(keys: Iterable[tuple[str, ...]]) -> list[tuple[str, .. else: roots.append(key) - ordered: list[tuple[str, ...]] = [] + ordered: list[tuple[tuple[str, ...], int]] = [] # Explicit stack rather than recursion: nesting depth is user-controlled. - stack = list(reversed(roots)) + stack = [(key, 0) for key in reversed(roots)] while stack: - key = stack.pop() - ordered.append(key) - stack.extend(reversed(children.get(key, []))) + key, depth = stack.pop() + ordered.append((key, depth)) + stack.extend((child, depth + 1) for child in reversed(children.get(key, []))) return ordered +def _top_level_time(timings: dict[tuple[str, ...], _TimesDict]) -> float: + """Sum the sections with no recorded parent, matching the roots of ``_ordered_by_hierarchy``. + + A parent goes missing when timings are cleared while it is active; its children that + finish afterwards are then top-level and must count toward the total. + """ + return sum( + (info["elapsed_time"] for key, info in timings.items() if len(key) == 1 or key[:-1] not in timings), + 0.0, + ) + + class _ExecutionTimer: """Registry of named, nestable timing sections, shared through ``_TIMER``.""" @@ -137,9 +151,10 @@ def start_timer(self, name: str, category: str) -> None: def stop_timer(self, name: str) -> None: """Stop timing a section and accumulate its elapsed time. - Never raises: an exception here would replace one already propagating from the timed - block. Exiting past still-active inner sections (typically a suspended generator that - holds one open) discards them with a warning, so the stack cannot stay corrupted. + Never raises, unless warnings are configured as errors: an exception here would replace + one already propagating from the timed block. Exiting past still-active inner sections + (typically a suspended generator that holds one open) discards them with a warning, + after recording the exit, so the stack cannot stay corrupted. Exiting a section that is no longer active, such as one discarded that way when its generator is finally closed, does nothing. """ @@ -150,17 +165,18 @@ def stop_timer(self, name: str) -> None: frame = frame.parent if frame is None: return + 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) 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 " "unfinished inner sections. Close sections before a generator yields." ) warnings.warn(msg, RuntimeWarning, stacklevel=3) - 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) def _resolve(self, *, flatten: bool) -> dict[tuple[str, ...], _TimesDict]: snapshot = self.snapshot() @@ -168,23 +184,25 @@ def _resolve(self, *, flatten: bool) -> dict[tuple[str, ...], _TimesDict]: def report_timings(self, *, flatten: bool = True) -> str: """Build a report of all sections with duration and percentage of total time.""" - timings = self._resolve(flatten=flatten) - if not timings: + snapshot = self.snapshot() + if not snapshot: return "" - total_time = sum(info["elapsed_time"] for key, info in timings.items() if len(key) == 1) + # Total the unflattened paths, like get_total_time and the JSON export. + total_time = _top_level_time(snapshot) + timings = _flatten(snapshot) if flatten else snapshot report = [f"Total time: {total_time:.4f} s.\n"] - for key in _ordered_by_hierarchy(timings): + for key, depth in _ordered_by_hierarchy(timings): elapsed_time = timings[key]["elapsed_time"] percentage = (elapsed_time / total_time) * 100 if total_time else 0.0 - report.append(f"{'.. ' * (len(key) - 1)}{key[-1]}: {elapsed_time:.4f} s ({percentage:.2f}%)") + report.append(f"{'.. ' * depth}{key[-1]}: {elapsed_time:.4f} s ({percentage:.2f}%)") return "\n".join(report) def compute_total_time(self) -> float: """Compute total elapsed time across all top-level sections.""" # Counter merging cannot change the sum, so there is no snapshot to copy or flatten. with self._lock: - return sum((info["elapsed_time"] for key, info in self.timings.items() if len(key) == 1), 0.0) + return _top_level_time(self.timings) def compute_total_category_time(self, category: str) -> float: """Compute total elapsed time in a category, counting only top-most entries of that category.""" @@ -344,7 +362,7 @@ def _build_payload(*, flatten: bool = True) -> TimingsPayload: "time": round(timings[key]["elapsed_time"], 6), "category": timings[key]["category"], } - for key in _ordered_by_hierarchy(timings) + for key, _ in _ordered_by_hierarchy(timings) ] category_totals: dict[str, float] = {} for key, info in snapshot.items(): @@ -352,7 +370,7 @@ def _build_payload(*, flatten: bool = True) -> TimingsPayload: if not _has_ancestor_with_category(snapshot, key, category): category_totals[category] = category_totals.get(category, 0.0) + info["elapsed_time"] return { - "total_time": round(sum((info["elapsed_time"] for key, info in snapshot.items() if len(key) == 1), 0.0), 6), + "total_time": round(_top_level_time(snapshot), 6), "total_category_time": {cat: round(category_totals[cat], 6) for cat in sorted(category_totals)}, "sections": sections, } diff --git a/tests/execution_timer_test.py b/tests/execution_timer_test.py index fb91fb5..8109567 100644 --- a/tests/execution_timer_test.py +++ b/tests/execution_timer_test.py @@ -7,6 +7,7 @@ import logging import threading import time +import warnings from collections.abc import AsyncIterator, Generator, Iterator from concurrent.futures import ThreadPoolExecutor from contextlib import ExitStack @@ -935,6 +936,23 @@ def numbers() -> Generator[int]: pass assert list(raw_timings()) == [("caller",), ("caller", "generator"), ("after",)] + def test_warnings_as_errors_still_record_and_unwind_before_raising(self) -> None: + def numbers() -> Generator[int]: + with TimerContext("generator"): + yield 1 + + paused = numbers() + with patch.object(time, "perf_counter", side_effect=[0, 1, 3]), warnings.catch_warnings(): + warnings.simplefilter("error", RuntimeWarning) + with pytest.raises(RuntimeWarning), TimerContext("caller"): + _ = next(paused) + raise KeyError("from the body") + paused.close() + with TimerContext("after"): + pass + assert raw_timings()["caller",]["time"] == 3.0 + assert list(raw_timings()) == [("caller",), ("caller", "generator"), ("after",)] + def test_exiting_a_section_that_is_not_active_leaves_the_stack_intact(self) -> None: with TimerContext("outer"): TimerContext("stranger").__exit__(None, None, None) @@ -952,12 +970,31 @@ def test_reports_preserve_orphaned_children_after_clear(self) -> None: with TimerContext("child", category="cpu"): pass assert list(raw_timings()) == [("parent", "child")] - assert "child: 2.0000 s (0.00%)" in get_execution_times_report() + # The cleared parent is gone, so its child is top-level: it counts toward the total + # and is not indented beneath an unrelated section. + assert get_execution_times_report() == "Total time: 2.0000 s.\n\nchild: 2.0000 s (100.00%)" + assert get_total_time() == 2.0 payload = cast(TimingsPayload, json.loads(get_execution_times_json())) - assert payload["total_time"] == 0.0 + assert payload["total_time"] == 2.0 assert payload["total_category_time"] == {"cpu": 2.0} assert payload["sections"][0]["path"] == ["parent", "child"] + def test_periodic_clear_inside_an_outer_section_reports_each_interval(self) -> None: + clock = [0, 1, 2, 3, 4, 10, 11, 12, 14, 20, 30, 31] + with patch.object(time, "perf_counter", side_effect=clock): + with TimerContext("main"): + for batch in range(2): + with TimerContext("load"), TimerContext("parse"): + pass + if batch == 0: + clear_execution_timings() + with TimerContext("after"): + pass + assert get_execution_times_report() == ( + "Total time: 5.0000 s.\n\nload: 4.0000 s (80.00%)\n.. parse: 1.0000 s (20.00%)\nafter: 1.0000 s (20.00%)" + ) + assert get_total_time() == 5.0 + def test_deep_reports_do_not_depend_on_python_recursion_limit(self) -> None: with ExitStack() as stack: for _ in range(1_100): From 1480233b3b5e24b6b7f55435dc78780e38826c31 Mon Sep 17 00:00:00 2001 From: Sebastian Yde Madsen <75695915+seba2390@users.noreply.github.com> Date: Wed, 30 Sep 2026 22:30:56 +0200 Subject: [PATCH 2/2] Release 1.0.1 Require hatchling>=1.27, the first release supporting the PEP 639 license-files metadata the project declares, and group Dependabot's monthly updates into one pull request per ecosystem. --- .github/dependabot.yml | 6 ++++++ CHANGELOG.md | 23 ++++++++++++++++++++++- pyproject.toml | 3 ++- src/execution_timer/__init__.py | 2 +- 4 files changed, 31 insertions(+), 3 deletions(-) diff --git a/.github/dependabot.yml b/.github/dependabot.yml index cc09045..c5675b9 100644 --- a/.github/dependabot.yml +++ b/.github/dependabot.yml @@ -6,6 +6,9 @@ updates: interval: "monthly" commit-message: prefix: "ci" + groups: + actions: + patterns: ["*"] - package-ecosystem: "uv" directory: "/" @@ -13,3 +16,6 @@ updates: interval: "monthly" commit-message: prefix: "build" + groups: + dev-dependencies: + patterns: ["*"] diff --git a/CHANGELOG.md b/CHANGELOG.md index 5682a50..f72c575 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,26 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +## [1.0.1] - 2026-09-30 + +### Fixed + +- Exiting a section while an inner one is still active no longer leaves the active stack + corrupted when warnings are configured as errors (for example pytest's + `filterwarnings = ["error"]`). The `RuntimeWarning` was emitted before the exit was + recorded, so raising it skipped the cleanup that 1.0.0 introduced. The section is now + recorded and the stack unwound before the warning is emitted. +- Sections whose parent was cleared while active now count as top-level. Previously, + clearing timings inside an outer section, such as a periodic clear in a long-running + loop, made `get_total_time()`, the report and the JSON `total_time` read `0`, every + percentage `0.00%`, and indented the sections beneath an unrelated one in the report. + +### Changed + +- The build requires `hatchling>=1.27`, the first release that supports the PEP 639 + `license-files` metadata the project declares. +- Dependabot groups its monthly updates into one pull request per ecosystem. + ## [1.0.0] - 2026-09-30 First stable release. The public API is now covered by semantic versioning: breaking @@ -129,7 +149,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.0...HEAD +[Unreleased]: https://github.com/seba2390/ExecutionTimer/compare/v1.0.1...HEAD +[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 [0.2.0]: https://github.com/seba2390/ExecutionTimer/compare/v0.1.1...v0.2.0 [0.1.1]: https://github.com/seba2390/ExecutionTimer/compare/v0.1.0...v0.1.1 diff --git a/pyproject.toml b/pyproject.toml index 5a605ce..d9bb519 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -44,7 +44,8 @@ Issues = "https://github.com/seba2390/ExecutionTimer/issues" Changelog = "https://github.com/seba2390/ExecutionTimer/blob/main/CHANGELOG.md" [build-system] -requires = ["hatchling"] +# 1.27 is the first release that supports PEP 639 license metadata (license-files). +requires = ["hatchling>=1.27"] build-backend = "hatchling.build" [tool.hatch.version] diff --git a/src/execution_timer/__init__.py b/src/execution_timer/__init__.py index 681644d..029723e 100644 --- a/src/execution_timer/__init__.py +++ b/src/execution_timer/__init__.py @@ -18,7 +18,7 @@ save_execution_timings_json, ) -__version__ = "1.0.0" +__version__ = "1.0.1" __all__ = [ "DEFAULT_CATEGORY",