Release 1.0.1: keep timings consistent after warnings-as-errors and mid-section clears

.github/dependabot.yml

@@ -6,10 +6,16 @@ updates:
       interval: "monthly"
     commit-message:
       prefix: "ci"
+    groups:
+      actions:
+        patterns: ["*"]
 
   - package-ecosystem: "uv"
     directory: "/"
     schedule:
       interval: "monthly"
     commit-message:
       prefix: "build"
+    groups:
+      dev-dependencies:
+        patterns: ["*"]

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

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

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]

src/execution_timer/__init__.py

@@ -18,7 +18,7 @@
     save_execution_timings_json,
 )
 
-__version__ = "1.0.0"
+__version__ = "1.0.1"
 
 __all__ = [
     "DEFAULT_CATEGORY",

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,41 +165,44 @@ 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()
         return _flatten(snapshot) if flatten else snapshot
 
     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,15 +362,15 @@ 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():
         category = info["category"]
         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,
     }

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):