From 4efbc16c49e7c8c7e81dcbec8cf0e14ab0e92dfe Mon Sep 17 00:00:00 2001 From: Sebastian Yde Madsen <75695915+seba2390@users.noreply.github.com> Date: Wed, 30 Sep 2026 23:52:53 +0200 Subject: [PATCH 1/2] =?UTF-8?q?Show=20report=20times=20in=20=C2=B5s,=20ms?= =?UTF-8?q?=20or=20s=20so=20fast=20sections=20stay=20visible?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The text report printed seconds with four decimals, so any section under 50 µs read 0.0000 s; a whole recursive fib(6) call tree came out as zeros. Each time now has three decimals in the largest of µs, ms and s that keeps the number below 1000, picked after rounding so 999.9996 µs reads 1.000 ms. The dictionary and JSON readers are unchanged and still return seconds. Docs examples show real output from the new format. --- CHANGELOG.md | 10 ++++++++++ README.md | 10 +++++----- docs/getting-started.md | 14 +++++++------- docs/guide/counters.md | 10 +++++----- docs/guide/reports.md | 20 ++++++++++++-------- docs/guide/timing-code.md | 8 ++++---- docs/index.md | 10 +++++----- src/execution_timer/_timer.py | 23 +++++++++++++++++++---- tests/execution_timer_test.py | 25 ++++++++++++++++++++++--- 9 files changed, 89 insertions(+), 41 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 43e40f9..8715677 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,16 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### 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 diff --git a/README.md b/README.md index 407d5b7..10a9785 100644 --- a/README.md +++ b/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: diff --git a/docs/getting-started.md b/docs/getting-started.md index f96d9fb..c5eccbb 100644 --- a/docs/getting-started.md +++ b/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: diff --git a/docs/guide/counters.md b/docs/guide/counters.md index e05b4af..822d78f 100644 --- a/docs/guide/counters.md +++ b/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 diff --git a/docs/guide/reports.md b/docs/guide/reports.md index 4b26aa8..4f8bcc8 100644 --- a/docs/guide/reports.md +++ b/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 diff --git a/docs/guide/timing-code.md b/docs/guide/timing-code.md index ead174d..5ab7e7d 100644 --- a/docs/guide/timing-code.md +++ b/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 diff --git a/docs/index.md b/docs/index.md index 2ee3af2..bc7d579 100644 --- a/docs/index.md +++ b/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 diff --git a/src/execution_timer/_timer.py b/src/execution_timer/_timer.py index 7894dd6..c826347 100644 --- a/src/execution_timer/_timer.py +++ b/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``. diff --git a/tests/execution_timer_test.py b/tests/execution_timer_test.py index 822c13a..14cca80 100644 --- a/tests/execution_timer_test.py +++ b/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 From 56e73a9d4d12cf6f6509d466c8cb096d7f491f15 Mon Sep 17 00:00:00 2001 From: Sebastian Yde Madsen <75695915+seba2390@users.noreply.github.com> Date: Wed, 30 Sep 2026 23:54:39 +0200 Subject: [PATCH 2/2] Release 1.1.0 Bump __version__ to 1.1.0 and move the report-units entry into its changelog section. The report text changes format, so this is a minor release rather than a patch. Also correct the getting-started percentage that the refreshed example output no longer matched, explain the report units there, and update the bug template's version placeholder. --- .github/ISSUE_TEMPLATE/bug_report.yml | 2 +- CHANGELOG.md | 5 ++++- docs/getting-started.md | 6 ++++-- src/execution_timer/__init__.py | 2 +- 4 files changed, 10 insertions(+), 5 deletions(-) diff --git a/.github/ISSUE_TEMPLATE/bug_report.yml b/.github/ISSUE_TEMPLATE/bug_report.yml index 4be4b9d..e14b20e 100644 --- a/.github/ISSUE_TEMPLATE/bug_report.yml +++ b/.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 diff --git a/CHANGELOG.md b/CHANGELOG.md index 8715677..c523e3b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,8 @@ 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 @@ -204,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 diff --git a/docs/getting-started.md b/docs/getting-started.md index c5eccbb..9c492dd 100644 --- a/docs/getting-started.md +++ b/docs/getting-started.md @@ -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. diff --git a/src/execution_timer/__init__.py b/src/execution_timer/__init__.py index e779e34..fd68f1b 100644 --- a/src/execution_timer/__init__.py +++ b/src/execution_timer/__init__.py @@ -18,7 +18,7 @@ save_execution_timings_json, ) -__version__ = "1.0.3" +__version__ = "1.1.0" __all__ = [ "DEFAULT_CATEGORY",