Skip to content

[adapters] Fix the tick-accounting race in test_clock - #6740

Merged
ryzhyk merged 1 commit into
mainfrom
fix-clock-test-tick-accounting
Jul 28, 2026
Merged

[adapters] Fix the tick-accounting race in test_clock#6740
ryzhyk merged 1 commit into
mainfrom
fix-clock-test-tick-accounting

Conversation

@ryzhyk

@ryzhyk ryzhyk commented Jul 28, 2026

Copy link
Copy Markdown
Contributor

Makes transport::clock::test::test_clock count replayed clock ticks against a baseline that cannot race the pipeline, which is what failed in the merge queue (assertion failed: ticks >= ticks_after_checkpoint && ticks <= ticks_after_checkpoint + 1). The failure cancelled every other job in that run; nothing was wrong with the change under test (#6718).

Why it failed

Both sides of the assertion were off by one, in opposite directions. The job's own replay log names the journaled steps (7 through 12, so six of them):

Term Reported in CI Ground truth Cause
ticks_after_checkpoint 5 6 journaled steps Sampled right after controller.pause(). Pause is asynchronous, so a step that races it is still journaled, and hence still replayed, while its tick goes uncounted.
replayed ticks 7 6 replayed + 1 live Once replay ends, the first step commits the last replayed transaction, and input_step queues every connector on that step regardless of the paused state, so the clock connector answers with a live tick.

The second row is systematic: locally the test reports 6 journaled and 7 replayed on every run, landing exactly on the assertion's upper bound. The + 1 allowance is therefore already spent, and a single miscounted tick in Run 1 fails the test. That is why the tolerance has been retuned four times (± 2, then exact, then + 1) and why #4516 came back.

The change

  • Take Run 1's post-checkpoint baseline after stop, which joins the circuit thread and so counts every journaled step.
  • Wait for the replayed ticks (settled_ticks) instead of sleeping a fixed five seconds, then read the count after a short settle, so neither a slow replay nor an overshoot can hide.
  • Record why one extra tick is legitimate, and report both counts when the assertion fires.

Validation

Scenario Before After
Normal run passes with zero margin (6 → 7) passes (6 → 7), 22.2s instead of 25.2s
One extra post-checkpoint step journaled after the old sampling point, which is the CI condition fails with the same assertion (6 → 9) passes (7 → 8)
Replay stops flushing its record not run fails (1 → 6), so the test still catches a broken replay
Whole transport::clock module 7 passed

A duplicate replay push stays invisible here because same-value records coalesce in the zset. That is harmless in production: the compiler consumes now as map_index -> chain_aggregate(max) -> deindex, so a repeated timestamp is idempotent.

Note on the live tick after replay

A pipeline resumed from a checkpoint and left paused still runs one step and advances NOW() by up to one clock resolution. NOW() only moves forward and the aggregate is idempotent, so there is no data impact, and this PR leaves the behaviour alone rather than changing the controller's step logic to fix a test.

🤖 Generated with Claude Code

@ryzhyk
ryzhyk requested a review from blp July 28, 2026 15:57

@mythical-fred mythical-fred left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Solid diagnosis and a well-scoped fix.

The two off-by-ones are correctly identified: pause is asynchronous so the baseline was one short, and input_step unconditionally polls the clock connector on the first live step after replay, which spends the + 1 allowance systematically. Moving the baseline read after controller.stop() (which joins the circuit thread) and gating Run 2's read on settled_ticks(&stats, expected) closes both directions of the race without weakening the assertion.

A few small notes, none blocking:

  • settled_ticks polls until ticks >= expected, then sleeps SETTLE = 2s and returns. That is exactly what you want for detecting the +1 overshoot without accepting a stalled replay. Worth adding a comment that the 2s settle is intentionally chosen to be larger than one clock resolution so an overshoot cannot hide behind the deadline.
  • The failure message now reports both ticks and ticks_after_checkpoint — good. Consider also printing the failure-mode class ("replay stalled" vs "extra live tick") if this ever flakes again, but only if it flakes again.
  • The Note on the live tick after replay in the PR body is the interesting bit for future readers. Worth mirroring one sentence of it into a // TODO/// NOTE in the source next to the + 1 allowance so the next person who touches this doesn't retune the tolerance for the fifth time.

Approving.

Comment thread crates/adapters/src/transport/clock.rs
@ryzhyk
ryzhyk force-pushed the fix-clock-test-tick-accounting branch from dc0359f to 1b148a8 Compare July 28, 2026 18:09
The test sampled Run 1's post-checkpoint tick count right after
`controller.pause()`. Pause is asynchronous, so a step that raced it was
still journaled, and hence still replayed, while its tick went uncounted:
the baseline came out one short of what Run 2 replays.

The assertion allows one extra replayed tick, but that allowance is
already spent. Once replay ends, the first step commits the last replayed
transaction, and `input_step` queues every connector on that step
regardless of the paused state, so the clock connector answers with a live
tick. Run 2 therefore replays the journaled ticks plus one every time,
which leaves no room for a miscounted tick in Run 1.

Take the baseline after `stop`, which joins the circuit thread and so
counts every journaled step, and wait for the replayed ticks instead of
sleeping a fixed five seconds, so a slow replay cannot be sampled halfway
through.

Failure: https://github.com/feldera/feldera/actions/runs/30334386760/job/90198147938
Previously reported as #4516.
@ryzhyk
ryzhyk force-pushed the fix-clock-test-tick-accounting branch from 1b148a8 to 1834663 Compare July 28, 2026 18:10
@ryzhyk
ryzhyk enabled auto-merge July 28, 2026 18:10
@ryzhyk
ryzhyk added this pull request to the merge queue Jul 28, 2026
Merged via the queue into main with commit 9521770 Jul 28, 2026
1 check passed
@ryzhyk
ryzhyk deleted the fix-clock-test-tick-accounting branch July 28, 2026 19:47
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.

3 participants