Skip to content

Fix profile measurements and make the instrument cheap - #8

Merged
devRMA merged 2 commits into
fix/timing-correctnessfrom
fix/profile-and-utils
Aug 2, 2026
Merged

Fix profile measurements and make the instrument cheap#8
devRMA merged 2 commits into
fix/timing-correctnessfrom
fix/profile-and-utils

Conversation

@devRMA

@devRMAdevRMA commented Aug 2, 2026

Copy link
Copy Markdown
Owner

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 known limitations, documented in the profile() docstring rather
than fixed:
a generator function is still only measured for building
the generator, because timing its 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). Capping that means reservoir sampling or dropping the median.

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 <unknown>. 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 noreply@anthropic.com


Stack created with GitHub Stacks CLIGive Feedback 💬

@vercel

vercelBot commented Aug 2, 2026

Copy link
Copy Markdown

The latest updates on your projects. Learn more about Vercel for GitHub.

ProjectDeploymentActionsUpdated (UTC)
stopwatch2-omipErrorErrorAug 2, 2026 8:59pm

devRMAand others added 2 commits August 2, 2026 17:59
`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 `<unknown>`. `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 <noreply@anthropic.com>
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 <noreply@anthropic.com>
@devRMA
devRMAforce-pushed the fix/profile-and-utils branch from 43d1f27 to 75dfbceCompareAugust 2, 2026 20:59
@devRMA
devRMA merged commit 4672de7 into mainAug 2, 2026
8 of 16 checks passed
@devRMA
devRMA deleted the fix/profile-and-utils branch August 2, 2026 21:22
Sign up for freeto join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant

@devRMA