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 43e40f9..c523e3b 100644 --- a/CHANGELOG.md +++ b/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 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..9c492dd 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: @@ -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/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/__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", 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