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/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/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", 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):