Release 1.1.0: show report times in µs, ms or s so fast sections stay visible

.github/ISSUE_TEMPLATE/bug_report.yml

@@ -23,7 +23,7 @@ body:
     id: version
     attributes:
       label: executiontimer version
-      placeholder: "1.0.0"
+      placeholder: "1.1.0"
     validations:
       required: true
 

CHANGELOG.md

@@ -7,6 +7,18 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [Unreleased]
 
+## [1.1.0] - 2026-09-30
+
+### Changed
+
+- The text report, from `get_execution_times_report()` and `log_execution_times()`, shows
+  each time with three decimals in `µs`, `ms` or `s`, whichever keeps the number below
+  1000: `48.213 µs`, `315.612 ms`, `2.500 s`. It used to show seconds with four
+  decimals, so any section under 50 µs read `0.0000 s`, and fast sections, including a
+  whole recursive call tree, looked like zeros. Code that parses the report text needs
+  updating. `get_execution_timings()` and the JSON export are unchanged and still return
+  seconds.
+
 ## [1.0.3] - 2026-09-30
 
 ### Changed
@@ -194,7 +206,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.3...HEAD
+[Unreleased]: https://github.com/seba2390/ExecutionTimer/compare/v1.1.0...HEAD
+[1.1.0]: https://github.com/seba2390/ExecutionTimer/compare/v1.0.3...v1.1.0
 [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

README.md

@@ -53,12 +53,12 @@ print(get_execution_times_report())
 ```
 
 ```text
-Total time: 0.3156 s.
+Total time: 312.838 ms.
 
-load_data: 0.1219 s (38.62%)
-solve: 0.1937 s (61.38%)
-..  step: 0.1585 s (50.24%)
-..  postprocess: 0.0350 s (11.10%)
+load_data: 124.682 ms (39.85%)
+solve: 188.157 ms (60.15%)
+..  step: 154.718 ms (49.46%)
+..  postprocess: 33.295 ms (10.64%)
 ```
 
 `TimerContext` also works as a decorator, including on `async def` functions:

docs/getting-started.md

@@ -42,9 +42,9 @@ print(get_execution_times_report())
 ```
 
 ```text
-Total time: 0.1035 s.
+Total time: 104.727 ms.
 
-load_data: 0.1035 s (100.00%)
+load_data: 104.727 ms (100.00%)
 ```
 
 Timings are recorded in one registry for the whole process. Every section you time, in any
@@ -72,12 +72,12 @@ print(get_execution_times_report())
 ```
 
 ```text
-Total time: 0.0905 s.
+Total time: 89.826 ms.
 
-pipeline: 0.0905 s (100.00%)
-..  load: 0.0232 s (25.60%)
-..  transform: 0.0673 s (74.32%)
-..  ..  validate: 0.0126 s (13.88%)
+pipeline: 89.826 ms (100.00%)
+..  load: 22.073 ms (24.57%)
+..  transform: 67.726 ms (75.40%)
+..  ..  validate: 12.549 ms (13.97%)
 ```
 
 How to read the report:
@@ -86,8 +86,10 @@ How to read the report:
   `pipeline`.
 - **Total time** is the sum of the top-level sections. Nested sections are part of their
   parent's time, so they aren't added again.
-- **Percentages** are shares of the total, at every level. `validate` took 13.88% of the
-  whole run, not 13.88% of `transform`.
+- **Percentages** are shares of the total, at every level. `validate` took 13.97% of the
+  whole run, not 13.97% of `transform`.
+- **Times** have three decimals, in `µs`, `ms` or `s`, whichever keeps the number below
+  1000, so even very fast sections show a real value.
 
 Calling {func}`~execution_timer.clear_execution_timings` starts over with an empty
 registry.

docs/guide/counters.md

@@ -37,12 +37,12 @@ print(get_execution_times_report(flatten=False))
 ```
 
 ```text
-Total time: 0.0724 s.
+Total time: 67.003 ms.
 
-solve: 0.0724 s (100.00%)
-..  step[0]: 0.0125 s (17.31%)
-..  step[1]: 0.0250 s (34.60%)
-..  step[2]: 0.0347 s (47.97%)
+solve: 67.003 ms (100.00%)
+..  step[0]: 12.542 ms (18.72%)
+..  step[1]: 23.851 ms (35.60%)
+..  step[2]: 30.498 ms (45.52%)
 ```
 
 Use the separate view to find a slow iteration, and the merged view to see the loop's

docs/guide/reports.md

@@ -32,16 +32,20 @@ print(get_execution_times_report())
 ```
 
 ```text
-Total time: 0.0499 s.
+Total time: 48.159 ms.
 
-load_data: 0.0249 s (49.92%)
-solve: 0.0250 s (50.08%)
-..  step: 0.0249 s (49.97%)
+load_data: 24.199 ms (50.25%)
+solve: 23.960 ms (49.75%)
+..  step: 23.904 ms (49.64%)
 ```
 
 Sections appear depth-first, each followed by its children, in the order they were first
 entered. Percentages are shares of the total time at every level.
 
+Times have three decimals, in `µs`, `ms` or `s`, whichever keeps the number below 1000.
+A 48 µs section reads `48.213 µs` rather than rounding to zero. The dictionary and JSON
+readers below return plain seconds.
+
 ## Logging
 
 {func}`~execution_timer.log_execution_times` logs the same report at `INFO` level, starting
@@ -58,11 +62,11 @@ log_execution_times()
 
 ```text
 INFO:execution_timer._timer:
-Total time: 0.0499 s.
+Total time: 48.159 ms.
 
-load_data: 0.0249 s (49.92%)
-solve: 0.0250 s (50.08%)
-..  step: 0.0249 s (49.97%)
+load_data: 24.199 ms (50.25%)
+solve: 23.960 ms (49.75%)
+..  step: 23.904 ms (49.64%)
 ```
 
 It logs to the `execution_timer._timer` logger unless you pass your own with

docs/guide/timing-code.md

@@ -152,11 +152,11 @@ print(get_execution_times_report())
 ```
 
 ```text
-Total time: 0.0354 s.
+Total time: 34.704 ms.
 
-walk: 0.0354 s (100.00%)
-..  walk: 0.0247 s (69.77%)
-..  ..  walk: 0.0125 s (35.38%)
+walk: 34.704 ms (100.00%)
+..  walk: 24.161 ms (69.62%)
+..  ..  walk: 11.603 ms (33.44%)
 ```
 
 For deep recursion, time the top-level call only, for example with a `with` block around

docs/index.md

@@ -23,12 +23,12 @@ print(get_execution_times_report())
 ```
 
 ```text
-Total time: 0.3156 s.
+Total time: 312.838 ms.
 
-load_data: 0.1219 s (38.62%)
-solve: 0.1937 s (61.38%)
-..  step: 0.1585 s (50.24%)
-..  postprocess: 0.0350 s (11.10%)
+load_data: 124.682 ms (39.85%)
+solve: 188.157 ms (60.15%)
+..  step: 154.718 ms (49.46%)
+..  postprocess: 33.295 ms (10.64%)
 ```
 
 ## Why executiontimer

src/execution_timer/__init__.py

@@ -18,7 +18,7 @@
     save_execution_timings_json,
 )
 
-__version__ = "1.0.3"
+__version__ = "1.1.0"
 
 __all__ = [
     "DEFAULT_CATEGORY",

src/execution_timer/_timer.py

@@ -198,11 +198,11 @@ def report_timings(self, *, flatten: bool = True) -> str:
         # 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"]
+        report = [f"Total time: {_format_duration(total_time)}.\n"]
         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"{'..  ' * depth}{key[-1]}: {elapsed_time:.4f} s ({percentage:.2f}%)")
+            report.append(f"{'..  ' * depth}{key[-1]}: {_format_duration(elapsed_time)} ({percentage:.2f}%)")
         return "\n".join(report)
 
     def compute_total_time(self) -> float:
@@ -243,6 +243,20 @@ def clear_forbidden_nesting(self) -> None:
 _TIMER: Final = _ExecutionTimer()
 
 
+def _format_duration(seconds: float) -> str:
+    """Format seconds with three decimals in the largest of µs, ms and s that stays below 1000.
+
+    The unit is chosen after rounding, so 999.9996 µs reads ``1.000 ms`` rather than
+    ``1000.000 µs``. Sections of any length stay readable, where fixed seconds would show a
+    fast section as zero.
+    """
+    for scale, unit in ((1e6, "µs"), (1e3, "ms")):
+        scaled = seconds * scale
+        if round(scaled, 3) < 1000:
+            return f"{scaled:.3f} {unit}"
+    return f"{seconds:.3f} s"
+
+
 def _flatten(timings: dict[tuple[str, ...], _TimesDict]) -> dict[tuple[str, ...], _TimesDict]:
     flat_map: dict[tuple[str, ...], _TimesDict] = {}
     for key, info in timings.items():
@@ -378,8 +392,9 @@ def _basic_name_without_counter(name: str) -> str:
 def get_execution_times_report(*, flatten: bool = True) -> str:
     """Get a formatted, indented report of all recorded sections.
 
-    Each line shows a section's accumulated seconds and its share of the total time.
-    Indentation reflects nesting.
+    Each line shows a section's accumulated time and its share of the total time.
+    Indentation reflects nesting. Times have three decimals, in ``µs``, ``ms`` or ``s``,
+    whichever keeps the number below 1000.
 
     Args:
         flatten: Merge ``counter`` variants such as ``step[0]`` and ``step[1]`` into ``step``.

tests/execution_timer_test.py

@@ -208,6 +208,25 @@ def test_report_empty_when_no_timings(self, caplog: pytest.LogCaptureFixture) ->
             assert get_execution_times_report() == ""
         assert caplog.records == []
 
+    @pytest.mark.parametrize(
+        ("seconds", "expected"),
+        [
+            (0.0000004, "0.400 µs"),
+            (0.0000482134, "48.213 µs"),
+            (0.0009999994, "999.999 µs"),
+            (0.0009999996, "1.000 ms"),
+            (0.3156, "315.600 ms"),
+            (0.9999996, "1.000 s"),
+            (2.5, "2.500 s"),
+            (3725.0, "3725.000 s"),
+        ],
+    )
+    def test_report_picks_a_unit_that_keeps_short_sections_visible(self, seconds: float, expected: str) -> None:
+        with patch.object(time, "perf_counter", side_effect=[0.0, seconds]), TimerContext("section"):
+            pass
+
+        assert get_execution_times_report() == f"Total time: {expected}.\n\nsection: {expected} (100.00%)"
+
     def test_report_flatten_flag(self) -> None:
         with patch.object(time, "perf_counter", side_effect=[0, 1, 1, 2]):
             for i in range(2):
@@ -757,7 +776,7 @@ def test_report_renders_when_all_elapsed_times_are_zero(self) -> None:
             pass
 
         report = get_execution_times_report()
-        assert "instant: 0.0000 s (0.00%)" in report
+        assert "instant: 0.000 µs (0.00%)" in report
 
 
 class TestRobustness:
@@ -1059,7 +1078,7 @@ def test_reports_preserve_orphaned_children_after_clear(self) -> None:
         assert list(raw_timings()) == [("parent", "child")]
         # 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_execution_times_report() == "Total time: 2.000 s.\n\nchild: 2.000 s (100.00%)"
         assert get_total_time() == 2.0
         payload = cast(TimingsPayload, json.loads(get_execution_times_json()))
         assert payload["total_time"] == 2.0
@@ -1078,7 +1097,7 @@ def test_periodic_clear_inside_an_outer_section_reports_each_interval(self) -> N
             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%)"
+            "Total time: 5.000 s.\n\nload: 4.000 s (80.00%)\n..  parse: 1.000 s (20.00%)\nafter: 1.000 s (20.00%)"
         )
         assert get_total_time() == 5.0