Measure the streaming stripper against CPU time, not wall clock by danielhanchen · Pull Request #9035 · unslothai/unsloth · GitHub
Skip to content

Measure the streaming stripper against CPU time, not wall clock - #9035

Merged
danielhanchen merged 3 commits into
mainfrom
fix-streaming-stripper-timing
Aug 17, 2026
Merged

Measure the streaming stripper against CPU time, not wall clock#9035
danielhanchen merged 3 commits into
mainfrom
fix-streaming-stripper-timing

Conversation

@danielhanchen

@danielhanchen danielhanchen commented Aug 16, 2026

Copy link
Copy Markdown
Member
tests/test_streaming_stripper.py:468: in test_early_markup_is_not_slower_than_the_code_it_replaces
E   AssertionError: early markup cost 1.451s against the reference's 1.316s
E   assert 1.4506334609999385 <= (1.3157524960000728 * 1.1)

Cause

The test compares how much work two code paths do, with a 10% margin:

count = 1500
reference = min(elapsed(_reference_strip, count) for _ in range(3))
incremental = min(elapsed(StreamingMarkupStripper(ENABLED).strip, count) for _ in range(3))
assert incremental <= reference * 1.10

elapsed used time.perf_counter, which measures wall clock, which also measures whatever else the machine is doing. A 10% margin does not survive that. On a 4-vCPU runner with other pytest workers in flight it fails while the code under test has not changed.

time.process_time measures this process's CPU time. That is the quantity the assertion is actually about, and neighbours do not move it. The 10% margin is untouched and both min-of-3 samples stay.

What is and is not verified

I have not reproduced the original failure locally, so I cannot claim this is verified as a fix for that specific run. Three busy processes pinned to the same core slow both arms equally, so the ratio holds and both clocks pass (5 runs each, all green).

What is demonstrated is the mechanism, on identical work:

wall cpu
idle core 0.0161s 0.0160s
core shared with 3 busy processes 0.0599s 0.0150s

Wall clock inflates 3.7x under contention. CPU time does not move.

Whole file: 64 passed.

Which PR, and which side is wrong

Introduced by #8538 (2026-08-12), which added this test using time.perf_counter. The source it guards is fine and is untouched here; the test has measured the wrong quantity since it was written.

Robustification

process_time is coarser than perf_counter, and 0.0 <= 0.0 * 1.10 is true. A stopped clock, or a count someone lowers, would silently turn this into an assertion that cannot fail. Both arms now have to measure something, with a 0.05s floor that sits far below the ~1.3s each arm actually takes and far above the clock's resolution. Mutating elapsed to return 0.0:

AssertionError: reference arm measured 0.0000s; too small to compare against

Found while measuring whether the backend suite can run under pytest-xdist. This is the one failure in that set that is not an order dependency: it is a timing assertion that cannot share a machine, and I would rather fix the clock than widen the margin.

  E AssertionError: early markup cost 1.451s against the reference's 1.316s
  E assert 1.4506334609999385 <= (1.3157524960000728 * 1.1)

Introduced by #8538 (2026-08-12), which added the test with time.perf_counter.
The source it guards is fine and is untouched here; the test has measured the
wrong quantity since it was written.

It compares how much WORK two code paths do, with a 10% margin, but timed them
on the wall clock, which also measures whatever else the machine is running. A
10% margin does not survive that. On a 4-vCPU runner with other pytest workers
in flight it failed while the code under test had not changed.

process_time measures this process's CPU time, which is what the assertion is
about and what neighbours cannot move. The margin and the min-of-3 sampling are
untouched.

I have NOT reproduced the original failure locally, so this is not verified as a
fix for that specific run: three busy processes on the same core slow both arms
equally and the ratio holds. What is demonstrated is the mechanism, on identical
work:

  idle core:                  wall=0.0161s  cpu=0.0160s
  core shared with 3 hogs:    wall=0.0599s  cpu=0.0150s

Wall clock inflates 3.7x, CPU time does not move.

Robustification: process_time is coarser than perf_counter, and 0.0 <= 0.0 * 1.10
is true, so a stopped clock or a lowered count would silently turn this into an
assertion that cannot fail. Both arms now have to measure something. Checked by
mutating the clock to return 0.0:

  reference arm measured 0.0000s; too small to compare against

Whole file: 64 passed.
@danielhanchen
danielhanchen force-pushed the fix-streaming-stripper-timing branch from 14a773e to 9b5fc2a Compare August 17, 2026 01:17
@danielhanchen

Copy link
Copy Markdown
Member Author

@codex review

@chatgpt-codex-connector

Copy link
Copy Markdown

Codex Review: Didn't find any major issues. More of your lovely PRs please.

Reviewed commit: d31fcae3bf

ℹ️ About Codex in GitHub

Codex has been enabled to automatically review pull requests in this repo. Reviews are triggered when you

  • Open a pull request for review
  • Mark a draft as ready
  • Comment "@codex review".

If Codex has suggestions, it will comment; otherwise it will react with 👍.

When you sign up for Codex through ChatGPT, Codex can also answer questions or update the PR, like "@codex address that feedback".

@danielhanchen

Copy link
Copy Markdown
Member Author

@danielhanchen
danielhanchen merged commit 8030607 into main Aug 17, 2026
32 of 35 checks passed
@danielhanchen
danielhanchen deleted the fix-streaming-stripper-timing branch August 17, 2026 04:46
Sign up for free to 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