Repository navigation
fix: Use monotonic clocks for migration latency and FDv2 stream-init timing - #539
tanderson-ld wants to merge 6 commits into
Conversation
…timing Wall-clock steps (DST transitions via naive datetime.now(), NTP corrections, VM/container time resync) could report wildly wrong or negative migration-operation latencies, and could inflate or zero out the FDv2 stream-init durations reported in diagnostic events. Migration latency (sync and async) is now measured with a monotonic clock and delivered to the tracker as a timedelta, unchanged in type. FDv2 stream-init duration is measured monotonically from the real connection moment (the SSE Start action) rather than a wall-clock projection of the next attempt; the wall clock is kept only for the reported timestamp. The projected next-attempt baseline is removed, and the diagnostic accumulator now clamps durationMillis to a non-negative integer once for every caller. Teardown paths (clean close and unexpected event errors) clear the attempt baseline so a later reconnect failure cannot report a duration spanning the backoff sleep. SDK-3307
|
AI review comment: UPDATE — this is now RESOLVED in-PR (commit 56370ae); it is no longer deferred. The FDv2 stream-init undercount described below was a regression this PR's earlier Start-only stamping introduced (main recorded every attempt), so it was fixed here rather than deferred: the baseline is now re-stamped monotonically at each fault/teardown, so every connection attempt records one stream-init again, while keeping the correct monotonic durations. A three-agent re-review confirmed the fix (no Critical/High/Medium) and the tests were tightened to guard it. One narrow, genuinely pre-existing gap remains out of scope (see the end). Original tracking note follows for context. FDv2 failed stream-init records are undercounted during a sustained outageWhat. The FDv2 streaming synchronizers record a failed stream-init only when the connection attempt's start is observable. The initial connect's start is observable, and a connected-then-failed init is observable (the SSE Spec angle. The DIAG diagnostic-events spec calls for one stream-init entry per connection attempt, so this was a conformance gap. Scope / severity. Diagnostics-only. No impact on flag evaluation, data correctness, connection/retry behavior, or the FDv1-fallback latch. Fix shipped here. Re-stamp the baseline at each fault/teardown (not a projection, not cleared to None), matching the one-entry-per-attempt behavior the other server SDKs use. The trade: a reconnect-failure's duration now includes the library-owned backoff interval, since the SDK cannot observe the true reconnect start. Still out of scope (pre-existing on main, not a clock issue): a connection that gets a |
|
Need to address pending issue related to undercounting. Done. |
The prior change stamped the stream-init baseline only on a successful connect (SSE Start), so reconnect attempts that failed to connect went unrecorded -- during a sustained outage only ~1 of N failures was reported, a regression from main which recorded every attempt. Re-stamp the baseline monotonically at each fault/teardown so every attempt is counted again, while keeping the monotonic (non-negative) durations; a reconnect-failure duration now includes the library-owned backoff, which the SDK cannot see past. Also tightens the new tests (scripted-clock clean-close assertion with teeth against a stale baseline; async healthy-drop and clean-close mirrors) and fixes the import sorting flagged by the repo's pinned isort. SDK-3307
…tions After switching migration latency to a monotonic clock, the TrackingLatency tests failed on Windows before Python 3.13, where time.monotonic() has ~16ms resolution (GetTickCount64) and under-measured the 0.1s callable sleep to ~94ms. Assert a substantial measured latency with margin for clock granularity instead of >= the exact sleep duration. SDK-3307
| if action.headers.get(_LD_FD_FALLBACK_HEADER) == 'true': | ||
| fallback_requested = True | ||
| if isinstance(action, Start): | ||
| self._connection_attempt_started_monotonic = monotonic_seconds() |
There was a problem hiding this comment.
This should not be here.
The earlier revision changed stream-init recording behavior (stamping at the SSE Start event and recording one init per connection attempt). This restores main's recording structure exactly and changes only the clock source: - FDv2 stream-init duration and the next_attempt_start projection now use monotonic_seconds(); the reported stream-init timestamp and the three DataSourceErrorInfo timestamps stay on the wall clock. - The negative-elapsed clamp, the record-iff-baseline-set guard, and all Start/Fault control flow match main. - diagnostics.py reverted to main (per-site clamp retained, no central clamp). - Stream-init duration is measured as difference-of-floored-milliseconds on the monotonic clock, matching main's rounding exactly. No observable behavioral change versus main, verified by a three-agent review (general, security, adversarial) plus proof tests.
|
AI review comment: This PR has been reworked to a pure monotonic-clock substitution with no behavioral change (head Consequently the stream-init undercount and the projection inaccuracy noted above are pre-existing on |
Summary
Switches the two remaining wall-clock duration measurements in this SDK to the monotonic clock, found by the clock-monotonicity re-audit. Implements SDK-3307 (re-audit findings #39/#40/#41).
This is a pure clock-source substitution with no observable behavioral change versus
main. The recording structure, control flow, and public contracts are byte-for-bytemain; only the clock a duration is measured from changes. A wall-clock step (DST via naivedatetime.now(), NTP correction, VM/container time resync) can no longer distort these durations.Changes
Impl::util.monotonic_seconds()is the single monotonic seam (added in the sibling clock-monotonicity work; reused here).migrations/migrator.py,async_migrator.py): measured withmonotonic_seconds()and delivered toOpTracker.latencyas atimedelta— identical type and, under a stable clock, identical value; a backward step can no longer produce a negative latency. Finding added config option for events_uri #39 (HIGH).datasourcev2/streaming.py,async_streaming.py,streaming_common.py): the connection-attempt baseline and thenext_attempt_startprojection now usemonotonic_seconds(), and the duration is computed on the monotonic clock as a difference of floored milliseconds (matchingmain's rounding exactly). The wall clock is retained for the reportedtimestamp(viacurrent_time_millis()) and for the threeDataSourceErrorInfo.timeerror timestamps. Findings Send the toggle default value with flag request events #40 / coerce user keys to strings #41 (MED).main: the projectednext_attempt_startbaseline, the per-siteelapsed if elapsed >= 0 else 0clamp, the record-iff-baseline-set guard, and allStart/Faultcontrol flow are preserved.diagnostics.pyis unchanged.Deliberately unchanged (wall clock is correct — values communicated outside the process):
DataSourceErrorInfo.time, eventcreationDate, diagnosticdataSinceDate, the big-segments cross-process staleness stamp.Explicitly out of scope
The pre-existing FDv2 stream-init projection inaccuracy (a reconnect's recorded duration can be driven to the clamp by the backoff projection) and the related diagnostic-count behavior during a sustained outage exist identically on
mainand are not changed by this PR. An earlier revision of this PR reworked that behavior; it has been reverted so this change is a clock swap only. Those are diagnostics-only, affect no flag evaluation, data correctness, or retry behavior, and will be addressed separately if desired.Behavioral notes
Not a breaking change — every modified component is
Impl-internal, and behavior under a stable clock is unchanged. Note for test suites that time-travel: these measurements no longer followtime.time();freezegundoes not patchtime.monotonic()by default.Testing
Full suite passes (1774 passed, 371 DB-skipped); mypy, isort, pycodestyle clean. New tests assert the clock property without asserting new behavior: migration latency measured monotonically (sync + async, via a module-patched clock); FDv2 stream-init duration measured on the monotonic clock while the reported timestamp follows the wall clock (proven by advancing the monotonic clock while stepping the wall clock backward), plus the preserved negative-elapsed clamp and baseline-cleared skip. The migration latency assertions use a 50 ms floor to tolerate coarse monotonic granularity on pre-3.13 Windows.
A three-agent review (general, security, adversarial) plus proof tests confirmed no observable behavioral change versus
main.Same change-class as the merged python PR #537.
Note
Overview
Replaces wall-clock duration measurements with monotonic timing in two internal areas so NTP/DST jumps no longer skew reported durations.
Migration operations (
migrator.py,async_migrator.py): op latency is measured withmonotonic_seconds()and passed to the tracker as atimedeltainstead ofdatetime.now()deltas.FDv2 streaming (
streaming.py,async_streaming.py,streaming_common.py): connection-attempt baselines, retrynext_attempt_startprojections, and stream-init elapsed time use the monotonic clock; diagnostic timestamps still usecurrent_time_millis(), and errorDataSourceErrorInfo.timestays on the wall clock. The existing negative-elapsed clamp and “record only when baseline is set” behavior are unchanged.Adds focused tests for monotonic stream-init recording (sync + async) and migration executor latency; integration tests relax the minimum latency assertion (100ms → 50ms) to account for coarse monotonic resolution on some platforms.
Reviewed by Cursor Bugbot for commit 0b804ff. Bugbot is set up for automated code reviews on this repo. Configure here.