From 7836f7652bf19d81586db9e1fb9a6f6194670881 Mon Sep 17 00:00:00 2001 From: Rafael Martins Date: Sun, 2 Aug 2026 16:47:24 -0300 Subject: [PATCH 1/2] Fix profile measurements and make the instrument cheap `inspect_caller` used `inspect.stack()`, which builds a FrameInfo for every frame on the stack and reads each frame's source file to attach context lines. Measured on a 23-frame stack: 597us per call, with `inspect.findsource` invoked 7200 times per 300 calls. `sys._getframe` returns the identical Caller in 1.80us -- 332x faster. The visible effect is that `Stopwatch(print_report=True)` cost 376us to construct against 0.76us without it; it is now 0.86us of overhead. This matters because the library exists to measure performance with a clock whose resolution is 1e-9s, so the cost of the instrument was landing in the measurement. The stdlib's logging module uses sys._getframe for the same reason. `profile` fixes: - A call that raised was never recorded. `statistics.add` came after `func()` returned, so exactly the calls worth investigating were dropped: three 50ms calls that raised reported `hits=0`. Recording now happens in a `finally`. - `async def` functions were timed only for building the coroutine. `await asyncio.sleep(0.10)` reported 4.52us. Coroutine functions now get an async wrapper that awaits inside the measurement. - `report_every=0` raised ZeroDivisionError on the first call, and `report_every=-1` reported on every call because `len % -1 == 0` is always true. Both are rejected up front with a ValueError. - The atexit report duplicated the last inline report, printing the same line twice on exit. It now only fires for calls the inline report did not already cover, which also means it still flushes a trailing partial group. - `**kwargs: Any` became explicit keyword-only parameters, so a typo in an argument name is an error instead of being silently ignored. Two limitations are marked with ponytail comments rather than fixed: a generator function is still only measured for building the generator (timing consumption would change the function's semantics), and every recorded value is retained because the median needs them all (~3MB per 100k calls, held until the process exits). Other fixes: - `format_elapsed_time` compared the signed value against its thresholds, so any negative value fell through to the microsecond branch and -1h rendered as '-3600000000.00us'. It now picks the unit by magnitude. - `Statistics(values)` stored the caller's list by reference, so `add()` mutated it and later edits to it changed the statistics -- but only for a non-empty list, since an empty one is falsy and got replaced. It copies now, so both cases behave the same. - `Statistics.total` returned int 0 for no values while annotated float. - Added `Statistics.stdev` using `statistics.pstdev`, replacing `math.sqrt(statistics.variance)` duplicated in two callers, and dropping the `math` import from both. - `stopwatch/__init__.py` calls `colorama.just_fix_windows_console()`. colorama was a dependency purely for Windows console support and nothing ever initialized it, so on Windows the ANSI escapes were printed raw. Unlike `colorama.init()` this does not wrap sys.stdout, which a library should not do. `tests/mocks/inspect.py` is deleted. It faked `inspect.stack` with a fixed three-frame list, so the old `test_inspect_caller` asserted against the mock's own values and verified nothing -- switching to the real implementation made it report `unittest.case` where the test expected ``. `inspect_caller` is now tested for real, including the previously untested `offset` parameter. Coverage is 100% of lines and branches over 49 tests, verified on Python 3.10.20 and 3.14.6. Co-Authored-By: Claude Opus 5 --- stopwatch/__init__.py | 10 +++++ stopwatch/profile.py | 86 +++++++++++++++++++++++++++++--------- stopwatch/statistics.py | 14 ++++++- stopwatch/stopwatch.py | 3 +- stopwatch/utils.py | 38 +++++++++++++---- tests/mocks/inspect.py | 17 -------- tests/test_profile.py | 90 ++++++++++++++++++++++++++++++++++++++++ tests/test_statistics.py | 16 +++++++ tests/test_stopwatch.py | 10 +++++ tests/test_utils.py | 45 ++++++++++++++++---- 10 files changed, 272 insertions(+), 57 deletions(-) delete mode 100644 tests/mocks/inspect.py diff --git a/stopwatch/__init__.py b/stopwatch/__init__.py index e53007e..6a177ff 100644 --- a/stopwatch/__init__.py +++ b/stopwatch/__init__.py @@ -1,6 +1,16 @@ +from colorama import just_fix_windows_console + from .profile import profile from .statistics import Statistics from .stopwatch import Stopwatch from .utils import format_elapsed_time +# The reports are colored with ANSI escapes, which a Windows console only +# understands once virtual terminal processing is enabled. colorama was +# always a dependency for this, but nothing ever called it, so on Windows +# the escapes were printed raw. Unlike colorama.init(), this does not wrap +# sys.stdout, which a library has no business doing, and it is a no-op +# everywhere else. +just_fix_windows_console() + __all__ = ['Statistics', 'Stopwatch', 'format_elapsed_time', 'profile'] diff --git a/stopwatch/profile.py b/stopwatch/profile.py index da9753c..152bf2b 100644 --- a/stopwatch/profile.py +++ b/stopwatch/profile.py @@ -1,8 +1,8 @@ import atexit import functools -import math +import inspect from collections.abc import Callable -from typing import Any, TypeVar +from typing import Any, TypeVar, cast from colorama import Fore, Style @@ -47,7 +47,7 @@ def _make_report(caller: Caller, name: str, statistics: Statistics) -> str: f'min={format_elapsed_time(statistics.minimum)}', f'median={format_elapsed_time(statistics.median)}', f'max={format_elapsed_time(statistics.maximum)}', - f'dev={format_elapsed_time(math.sqrt(statistics.variance))}', + f'dev={format_elapsed_time(statistics.stdev)}', ] ) @@ -71,37 +71,85 @@ def _print_report(caller: Caller, name: str, statistics: Statistics) -> None: print(_make_report(caller, name, statistics)) -def profile(**kwargs: Any) -> Callable[[Callable[..., RT]], Callable[..., RT]]: +def profile( + *, + name: str | None = None, + report_every: int | None = 1, +) -> Callable[[Callable[..., RT]], Callable[..., RT]]: """ - Decorator for profiling the function. + Decorator for profiling the function. Must be called: `@profile()`. + + Works on regular and `async def` functions. Generator functions are + not supported -- see the note below. Parameters ---------- name : Optional[`str`] The name for the statistics. Default is the name of function. report_every : Optional[`int`] - The number of times to report the statistics. Default is 1. + Report once every this many calls, or `None` to only report when + the process exits. Default is 1. + + Raises + ------ + `ValueError` + If `report_every` is smaller than 1. + + ponytail: a generator function is measured only for the time it takes + to build the generator, not to consume it, because there is no way to + time the consumption without changing the function's semantics. + ponytail: every recorded call is kept, because the median needs all + the values, and the atexit registration holds them until the process + exits (~3MB per 100k calls). Cap it with a reservoir sample, or drop + the median, if profiling a hot function over a long run. """ + if report_every is not None and report_every < 1: + raise ValueError( + f'report_every must be >= 1 or None, got {report_every}' + ) + caller = inspect_caller() def decorator(func: Callable[..., RT]) -> Callable[..., RT]: - name: str = kwargs.get('name', func.__name__) - report_every: int = kwargs.get('report_every', 1) - should_report = report_every is not None - + stat_name = func.__name__ if name is None else name statistics = Statistics() - atexit.register(_print_report, caller, name, statistics) - @functools.wraps(func) - def wrapper(*args: object, **kwargs: object) -> RT: - with Stopwatch() as stopwatch: - result = func(*args, **kwargs) + def record(elapsed: float) -> None: + statistics.add(elapsed) + if ( + report_every is not None + and len(statistics) % report_every == 0 + ): + _print_report(caller, stat_name, statistics) + + def report_at_exit() -> None: + # Skip when the inline report above already covered this call + # count, which otherwise printed the same line twice. + if report_every is None or len(statistics) % report_every != 0: + _print_report(caller, stat_name, statistics) - statistics.add(stopwatch.elapsed) - if should_report and (len(statistics) % report_every) == 0: - _print_report(caller, name, statistics) + atexit.register(report_at_exit) - return result + if inspect.iscoroutinefunction(func): + + @functools.wraps(func) + async def async_wrapper(*args: object, **kwargs: object) -> Any: + stopwatch = Stopwatch() + try: + return await func(*args, **kwargs) + finally: + record(stopwatch.stop().elapsed) + + return cast('Callable[..., RT]', async_wrapper) + + @functools.wraps(func) + def wrapper(*args: object, **kwargs: object) -> RT: + stopwatch = Stopwatch() + try: + return func(*args, **kwargs) + finally: + # In a finally, so a call that raises is still recorded. + record(stopwatch.stop().elapsed) return wrapper diff --git a/stopwatch/statistics.py b/stopwatch/statistics.py index cb3a806..c0f1128 100644 --- a/stopwatch/statistics.py +++ b/stopwatch/statistics.py @@ -5,7 +5,11 @@ class Statistics: _values: list[float] def __init__(self, values: list[float] | None = None) -> None: - self._values = values or [] + # Copy: `values or []` aliased the caller's list, so add() mutated + # it and later edits to it silently changed the statistics -- but + # only for a non-empty list, since an empty one is falsy and got + # replaced. Same behaviour either way now. + self._values = list(values) if values else [] def add(self, value: float) -> None: """ @@ -41,13 +45,19 @@ def minimum(self) -> float: @property def total(self) -> float: """`float`: Return the total value in seconds.""" - return sum(self._values) + # sum([]) is int 0, and the annotation promises a float. + return float(sum(self._values)) @property def variance(self) -> float: """`float`: Return the variance in seconds.""" return statistics.pvariance(self._values) + @property + def stdev(self) -> float: + """`float`: Return the population standard deviation in seconds.""" + return statistics.pstdev(self._values) + def __len__(self) -> int: return len(self._values) diff --git a/stopwatch/stopwatch.py b/stopwatch/stopwatch.py index 481301c..ae8c117 100644 --- a/stopwatch/stopwatch.py +++ b/stopwatch/stopwatch.py @@ -1,6 +1,5 @@ from __future__ import annotations -import math from collections.abc import Iterator from contextlib import contextmanager from typing import Any @@ -176,7 +175,7 @@ def report(self) -> str: f'min={statistics.minimum:.{self.precision}f}s', f'median={statistics.median:.{self.precision}f}s', f'max={statistics.maximum:.{self.precision}f}s', - f'dev={math.sqrt(statistics.variance):.{self.precision}f}s', + f'dev={statistics.stdev:.{self.precision}f}s', ] ) diff --git a/stopwatch/utils.py b/stopwatch/utils.py index 0ff8d99..18d5318 100644 --- a/stopwatch/utils.py +++ b/stopwatch/utils.py @@ -1,4 +1,4 @@ -import inspect +import sys from typing import NamedTuple @@ -9,12 +9,30 @@ class Caller(NamedTuple): def inspect_caller(offset: int = 0) -> Caller: - stack = inspect.stack()[2 + offset] - module = inspect.getmodule(stack.frame) + """ + Describe the frame two levels above this call. + + Parameters + ---------- + offset : `int` + Extra frames to skip, for callers that add a level of their own. + + Returns + ------- + `Caller` + The module name, function name and line number of that frame. + """ + # sys._getframe over inspect.stack(): stack() builds a FrameInfo for + # every frame on the stack and reads each one's source file to attach + # context, which costs ~376us for a 23-frame stack against ~3.5us + # here. This is a library for measuring performance, so the cost of + # the instrument lands in the measurement. The stdlib's own logging + # module uses sys._getframe for the same reason. + frame = sys._getframe(2 + offset) return Caller( - module=module.__name__ if module else '', - function=stack.function, - line_number=stack.lineno, + module=frame.f_globals.get('__name__', ''), + function=frame.f_code.co_name, + line_number=frame.f_lineno, ) @@ -35,8 +53,12 @@ def format_elapsed_time(elapsed: float, precision: int = 2) -> str: The formatted elapsed time. """ ms = elapsed * 1e3 - if ms >= 1e3: + # Compare on the magnitude: a negative elapsed time fails every `>=` + # below and would otherwise be rendered in microseconds, so -1h came + # out as '-3600000000.00us'. + magnitude = abs(ms) + if magnitude >= 1e3: return f'{ms / 1e3:.{precision}f}s' - if ms >= 1: + if magnitude >= 1: return f'{ms:.{precision}f}ms' return f'{ms * 1e3:.{precision}f}μs' diff --git a/tests/mocks/inspect.py b/tests/mocks/inspect.py deleted file mode 100644 index d28fcae..0000000 --- a/tests/mocks/inspect.py +++ /dev/null @@ -1,17 +0,0 @@ -from dataclasses import dataclass - - -@dataclass -class StackMock: - frame: str - function: str - lineno: int - - -class InspectMock: - @staticmethod - def stack() -> list[StackMock]: - return [ - StackMock(frame='frame', function='function', lineno=2) - for _ in range(3) - ] diff --git a/tests/test_profile.py b/tests/test_profile.py index e15c2bb..b8d4ea4 100644 --- a/tests/test_profile.py +++ b/tests/test_profile.py @@ -1,3 +1,6 @@ +import asyncio +import sys +from collections.abc import Callable from unittest import TestCase from unittest.mock import MagicMock, patch @@ -109,3 +112,90 @@ def test_profile_with_report_every_none( decorated_func() self.assertEqual(func.call_count, 4) print_mock.assert_not_called() + + def test_profile_rejects_invalid_report_every(self) -> None: + with self.assertRaises(ValueError): + profile(report_every=0) + with self.assertRaises(ValueError): + profile(report_every=-1) + + @patch('builtins.print') + def test_profile_records_calls_that_raise( + self, print_mock: MagicMock + ) -> None: + registered: list[object] = [] + with patch('atexit.register', registered.append): + with patch('time.perf_counter', self.time_mock.perf_counter): + + @profile(name='boom') + def failing() -> None: + self.time_mock.increment(0.5) + raise RuntimeError('nope') + + for _ in range(2): + with self.assertRaises(RuntimeError): + failing() + # The measurement used to be discarded when the call raised, so + # exactly the calls worth investigating went unrecorded. + self.assertEqual(print_mock.call_count, 2) + report = print_mock.call_args[0][0] + self.assertIn('hits=2', report) + self.assertIn('mean=500.00ms', report) + + def test_profile_measures_async_functions(self) -> None: + totals: list[float] = [] + # Reached through sys.modules because `stopwatch/__init__.py` + # binds the name `profile` to the function, shadowing the + # submodule, so 'stopwatch.profile._print_report' does not resolve. + profile_module = sys.modules['stopwatch.profile'] + with ( + patch('atexit.register', lambda *a, **k: None), + patch.object( + profile_module, + '_print_report', + lambda caller, name, stats: totals.append(stats.total), + ), + ): + + @profile(name='coro') + async def work() -> str: + await asyncio.sleep(0.05) + return 'done' + + self.assertEqual(asyncio.run(work()), 'done') + + # Before the fix only the coroutine's creation was timed, which + # reported single-digit microseconds for this. + self.assertEqual(len(totals), 1) + self.assertGreaterEqual(totals[0], 0.05) + + @patch('builtins.print') + def test_profile_does_not_report_twice_at_exit( + self, print_mock: MagicMock + ) -> None: + registered: list[Callable[[], None]] = [] + with patch('atexit.register', registered.append): + with patch('time.perf_counter', self.time_mock.perf_counter): + func = MagicMock(__name__='dup') + decorated_func = profile()(func) + self.time_mock.increment(0.1) + decorated_func() + self.assertEqual(print_mock.call_count, 1) + registered[0]() + self.assertEqual(print_mock.call_count, 1) + + @patch('builtins.print') + def test_profile_flushes_unreported_calls_at_exit( + self, print_mock: MagicMock + ) -> None: + registered: list[Callable[[], None]] = [] + with patch('atexit.register', registered.append): + with patch('time.perf_counter', self.time_mock.perf_counter): + func = MagicMock(__name__='flush') + decorated_func = profile(report_every=2)(func) + for _ in range(3): + self.time_mock.increment(0.1) + decorated_func() + self.assertEqual(print_mock.call_count, 1) + registered[0]() + self.assertEqual(print_mock.call_count, 2) diff --git a/tests/test_statistics.py b/tests/test_statistics.py index 40ab187..90acd9c 100644 --- a/tests/test_statistics.py +++ b/tests/test_statistics.py @@ -46,6 +46,22 @@ def test_variance(self) -> None: self.stats.variance, statistics.pvariance(self.values) ) + def test_stdev(self) -> None: + self.assertEqual(self.stats.stdev, statistics.pstdev(self.values)) + + def test_does_not_alias_the_given_list(self) -> None: + values = [1.0, 2.0] + stats = Statistics(values) + stats.add(3.0) + # `values or []` used to store the caller's list by reference, so + # add() mutated it and later edits to it changed the statistics. + self.assertEqual(values, [1.0, 2.0]) + values.append(99.0) + self.assertEqual(len(stats), 3) + + def test_total_is_a_float_when_empty(self) -> None: + self.assertIsInstance(Statistics().total, float) + def test_to_dict(self) -> None: self.assertEqual( self.stats.to_dict(), diff --git a/tests/test_stopwatch.py b/tests/test_stopwatch.py index 1d17dc1..6718076 100644 --- a/tests/test_stopwatch.py +++ b/tests/test_stopwatch.py @@ -146,6 +146,16 @@ def test_stopwatch_without_autostart_still_starts_as_context(self) -> None: self.assertTrue(sw.running) self.assertEqual(sw.elapsed, 1.0) + def test_stopwatch_start_while_running_is_a_noop(self) -> None: + with patch('time.perf_counter', self.time_mock.perf_counter): + sw = Stopwatch() + self.time_mock.increment(1) + sw.start() + self.time_mock.increment(1) + sw.stop() + self.assertEqual(len(sw.laps), 1) + self.assertEqual(sw.elapsed, 2.0) + def test_stopwatch_lap_closes_on_exception(self) -> None: with patch('time.perf_counter', self.time_mock.perf_counter): sw = Stopwatch() diff --git a/tests/test_utils.py b/tests/test_utils.py index 922d130..945dbc9 100644 --- a/tests/test_utils.py +++ b/tests/test_utils.py @@ -1,10 +1,8 @@ +import inspect from unittest import TestCase -from unittest.mock import patch from stopwatch import utils -from .mocks.inspect import InspectMock - class UtilsTest(TestCase): def test_format_elapsed_time(self) -> None: @@ -16,9 +14,38 @@ def test_format_elapsed_time(self) -> None: self.assertEqual(utils.format_elapsed_time(0.0001, 0), '100μs') self.assertEqual(utils.format_elapsed_time(0.000001, 0), '1μs') - def test_inspect_caller(self) -> None: - with patch('inspect.stack', InspectMock.stack): - caller = utils.inspect_caller() - self.assertEqual(caller.module, '') - self.assertEqual(caller.function, 'function') - self.assertEqual(caller.line_number, 2) + def test_format_elapsed_time_picks_unit_by_magnitude(self) -> None: + # Negative values used to fail every `>=` and fall through to the + # microsecond branch, so -1h came out as '-3600000000.00μs'. + self.assertEqual(utils.format_elapsed_time(-3600, 2), '-3600.00s') + self.assertEqual(utils.format_elapsed_time(-1, 2), '-1.00s') + self.assertEqual(utils.format_elapsed_time(-0.1, 2), '-100.00ms') + self.assertEqual(utils.format_elapsed_time(-0.000001, 2), '-1.00μs') + self.assertEqual(utils.format_elapsed_time(0, 2), '0.00μs') + + def test_inspect_caller_describes_two_frames_up(self) -> None: + def helper() -> utils.Caller: + return utils.inspect_caller() + + frame = inspect.currentframe() + assert frame is not None + expected_line = frame.f_lineno + 1 + caller = helper() + + self.assertEqual(caller.module, __name__) + self.assertEqual( + caller.function, 'test_inspect_caller_describes_two_frames_up' + ) + self.assertEqual(caller.line_number, expected_line) + + def test_inspect_caller_offset_skips_extra_frames(self) -> None: + def inner() -> utils.Caller: + return utils.inspect_caller(offset=1) + + def outer() -> utils.Caller: + return inner() + + # offset=1 skips `outer`, landing on this test method instead. + self.assertEqual( + outer().function, 'test_inspect_caller_offset_skips_extra_frames' + ) From 75dfbce92c335c2a0e6e574edfdbda1bdbee58fd Mon Sep 17 00:00:00 2001 From: Rafael Martins Date: Sun, 2 Aug 2026 17:18:23 -0300 Subject: [PATCH 2/2] Let the code carry the explanation instead of comments Same cleanup as the branch below. The report cadence check becomes `is_report_due()`, which reads at both call sites and replaces the comment that explained why the atexit hook skips a repeat. The generator and retention limitations move from ponytail markers into a plain Notes section of the docstring, stating the behaviour without the rationale. Co-Authored-By: Claude Opus 5 --- stopwatch/__init__.py | 6 ------ stopwatch/profile.py | 28 +++++++++++++--------------- stopwatch/statistics.py | 5 ----- stopwatch/utils.py | 9 --------- tests/test_profile.py | 7 ------- tests/test_statistics.py | 2 -- tests/test_utils.py | 3 --- 7 files changed, 13 insertions(+), 47 deletions(-) diff --git a/stopwatch/__init__.py b/stopwatch/__init__.py index 6a177ff..0ee894a 100644 --- a/stopwatch/__init__.py +++ b/stopwatch/__init__.py @@ -5,12 +5,6 @@ from .stopwatch import Stopwatch from .utils import format_elapsed_time -# The reports are colored with ANSI escapes, which a Windows console only -# understands once virtual terminal processing is enabled. colorama was -# always a dependency for this, but nothing ever called it, so on Windows -# the escapes were printed raw. Unlike colorama.init(), this does not wrap -# sys.stdout, which a library has no business doing, and it is a no-op -# everywhere else. just_fix_windows_console() __all__ = ['Statistics', 'Stopwatch', 'format_elapsed_time', 'profile'] diff --git a/stopwatch/profile.py b/stopwatch/profile.py index 152bf2b..3f2c91c 100644 --- a/stopwatch/profile.py +++ b/stopwatch/profile.py @@ -95,13 +95,11 @@ def profile( `ValueError` If `report_every` is smaller than 1. - ponytail: a generator function is measured only for the time it takes - to build the generator, not to consume it, because there is no way to - time the consumption without changing the function's semantics. - ponytail: every recorded call is kept, because the median needs all - the values, and the atexit registration holds them until the process - exits (~3MB per 100k calls). Cap it with a reservoir sample, or drop - the median, if profiling a hot function over a long run. + Notes + ----- + A generator function is measured only for building the generator, not + for consuming it. Every recorded value is retained until the process + exits, since the median needs all of them. """ if report_every is not None and report_every < 1: raise ValueError( @@ -114,18 +112,19 @@ def decorator(func: Callable[..., RT]) -> Callable[..., RT]: stat_name = func.__name__ if name is None else name statistics = Statistics() - def record(elapsed: float) -> None: - statistics.add(elapsed) - if ( + def is_report_due() -> bool: + return ( report_every is not None and len(statistics) % report_every == 0 - ): + ) + + def record(elapsed: float) -> None: + statistics.add(elapsed) + if is_report_due(): _print_report(caller, stat_name, statistics) def report_at_exit() -> None: - # Skip when the inline report above already covered this call - # count, which otherwise printed the same line twice. - if report_every is None or len(statistics) % report_every != 0: + if not is_report_due(): _print_report(caller, stat_name, statistics) atexit.register(report_at_exit) @@ -148,7 +147,6 @@ def wrapper(*args: object, **kwargs: object) -> RT: try: return func(*args, **kwargs) finally: - # In a finally, so a call that raises is still recorded. record(stopwatch.stop().elapsed) return wrapper diff --git a/stopwatch/statistics.py b/stopwatch/statistics.py index c0f1128..203e37f 100644 --- a/stopwatch/statistics.py +++ b/stopwatch/statistics.py @@ -5,10 +5,6 @@ class Statistics: _values: list[float] def __init__(self, values: list[float] | None = None) -> None: - # Copy: `values or []` aliased the caller's list, so add() mutated - # it and later edits to it silently changed the statistics -- but - # only for a non-empty list, since an empty one is falsy and got - # replaced. Same behaviour either way now. self._values = list(values) if values else [] def add(self, value: float) -> None: @@ -45,7 +41,6 @@ def minimum(self) -> float: @property def total(self) -> float: """`float`: Return the total value in seconds.""" - # sum([]) is int 0, and the annotation promises a float. return float(sum(self._values)) @property diff --git a/stopwatch/utils.py b/stopwatch/utils.py index 18d5318..62a3a2f 100644 --- a/stopwatch/utils.py +++ b/stopwatch/utils.py @@ -22,12 +22,6 @@ def inspect_caller(offset: int = 0) -> Caller: `Caller` The module name, function name and line number of that frame. """ - # sys._getframe over inspect.stack(): stack() builds a FrameInfo for - # every frame on the stack and reads each one's source file to attach - # context, which costs ~376us for a 23-frame stack against ~3.5us - # here. This is a library for measuring performance, so the cost of - # the instrument lands in the measurement. The stdlib's own logging - # module uses sys._getframe for the same reason. frame = sys._getframe(2 + offset) return Caller( module=frame.f_globals.get('__name__', ''), @@ -53,9 +47,6 @@ def format_elapsed_time(elapsed: float, precision: int = 2) -> str: The formatted elapsed time. """ ms = elapsed * 1e3 - # Compare on the magnitude: a negative elapsed time fails every `>=` - # below and would otherwise be rendered in microseconds, so -1h came - # out as '-3600000000.00us'. magnitude = abs(ms) if magnitude >= 1e3: return f'{ms / 1e3:.{precision}f}s' diff --git a/tests/test_profile.py b/tests/test_profile.py index b8d4ea4..4277cd7 100644 --- a/tests/test_profile.py +++ b/tests/test_profile.py @@ -135,8 +135,6 @@ def failing() -> None: for _ in range(2): with self.assertRaises(RuntimeError): failing() - # The measurement used to be discarded when the call raised, so - # exactly the calls worth investigating went unrecorded. self.assertEqual(print_mock.call_count, 2) report = print_mock.call_args[0][0] self.assertIn('hits=2', report) @@ -144,9 +142,6 @@ def failing() -> None: def test_profile_measures_async_functions(self) -> None: totals: list[float] = [] - # Reached through sys.modules because `stopwatch/__init__.py` - # binds the name `profile` to the function, shadowing the - # submodule, so 'stopwatch.profile._print_report' does not resolve. profile_module = sys.modules['stopwatch.profile'] with ( patch('atexit.register', lambda *a, **k: None), @@ -164,8 +159,6 @@ async def work() -> str: self.assertEqual(asyncio.run(work()), 'done') - # Before the fix only the coroutine's creation was timed, which - # reported single-digit microseconds for this. self.assertEqual(len(totals), 1) self.assertGreaterEqual(totals[0], 0.05) diff --git a/tests/test_statistics.py b/tests/test_statistics.py index 90acd9c..4d7a0db 100644 --- a/tests/test_statistics.py +++ b/tests/test_statistics.py @@ -53,8 +53,6 @@ def test_does_not_alias_the_given_list(self) -> None: values = [1.0, 2.0] stats = Statistics(values) stats.add(3.0) - # `values or []` used to store the caller's list by reference, so - # add() mutated it and later edits to it changed the statistics. self.assertEqual(values, [1.0, 2.0]) values.append(99.0) self.assertEqual(len(stats), 3) diff --git a/tests/test_utils.py b/tests/test_utils.py index 945dbc9..ea31f4e 100644 --- a/tests/test_utils.py +++ b/tests/test_utils.py @@ -15,8 +15,6 @@ def test_format_elapsed_time(self) -> None: self.assertEqual(utils.format_elapsed_time(0.000001, 0), '1μs') def test_format_elapsed_time_picks_unit_by_magnitude(self) -> None: - # Negative values used to fail every `>=` and fall through to the - # microsecond branch, so -1h came out as '-3600000000.00μs'. self.assertEqual(utils.format_elapsed_time(-3600, 2), '-3600.00s') self.assertEqual(utils.format_elapsed_time(-1, 2), '-1.00s') self.assertEqual(utils.format_elapsed_time(-0.1, 2), '-100.00ms') @@ -45,7 +43,6 @@ def inner() -> utils.Caller: def outer() -> utils.Caller: return inner() - # offset=1 skips `outer`, landing on this test method instead. self.assertEqual( outer().function, 'test_inspect_caller_offset_skips_extra_frames' )