[core] Fix FormatTimeSys rendering the same timestamp inconsistently (#3225) - #3342
[core] Fix FormatTimeSys rendering the same timestamp inconsistently (#3225)#3342steps-re wants to merge 3 commits into
Conversation
FormatTimeSys mapped a steady-clock timestamp onto wall-clock time by combining whole-second wall time from ::time() with the sub-second part of steady_clock::now(). The two clocks have unrelated sub-second phases (steady counts from an arbitrary epoch such as boot), so near a second boundary the very same timestamp could render one second apart between calls (issue Haivision#3225). Map the timestamp using a single steady<->wall reference pair captured once at load time, in a consistent microsecond domain. This removes the +/-1 s flicker and also the ~1 us jitter that per-call re-sampling would cause, so a given timestamp always formats to exactly the same string. The mapping arithmetic is factored into a pure overload FormatTimeSys(target_us, steady_now_us, wall_now_us) so it can be unit tested deterministically. Adds a regression test (Sync.FormatTimeSysStable) that sweeps the "now" reference across steady/wall second boundaries with misaligned phases and asserts the output is stable. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> Signed-off-by: Mike German <mike@stepsventures.com>
|
That's a very good solution of the problem, but I don't like the way how the code is shaped. If the goal of providing a second FormatTimeSys function was to allow exposure of the raw values for the sake of the UT, this should be done more direct way. Sure, there's no other (reasonable) way to expose this for the UT than to place it in the header file, but this should be definitely presented as an internal version, not intended for any other use. So, in short, the Then the normal It might be also worth a shot to split the implementation of FormatTimeSysInternal into the part that does all these time value conversion in order to produce |
Replace the second FormatTimeSys overload with an explicitly internal API, as requested in review: - sync.h now declares SysClockReference (a steady<->wall clock sample pair) and FormatTimeSysInternal(time_point, SysClockReference), both marked as exposed for testing purposes only. - The public FormatTimeSys() keeps its single signature and obtains the reference as a function-local static (thread-safe, initialized on first use), then delegates to FormatTimeSysInternal. - The implementation is split into ToSysTimeMicroseconds (steady->wall mapping) and FormatSysTimeMicroseconds (text formatting). - The regression test now drives FormatTimeSysInternal with explicit SysClockReference values instead of raw int64_t triples. Signed-off-by: Mike German <mike@stepsventures.com> Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
|
reshaped as you suggested. SysClockReference and FormatTimeSysInternal now sit in the header under an "exposed for testing purposes only" banner, and the public FormatTimeSys keeps its single signature with the reference as a static local. also took your optional suggestion and split the internal impl into the steady-to-wall conversion and the text formatting. full suite passes locally, 276/276, and the regression test now goes through FormatTimeSysInternal. |
|
@ethouris bump when you get a chance. the reshape from your last review went in on the 28th and CI is green. happy to keep iterating if the shape still isn't what you had in mind. |
|
Sorry, we are a bit in a hot water now, hence the delay. Looks very good; if you can merge the latest |
|
merged latest master in, no conflicts, and it does not touch anything our diff does. built locally with unit tests on, full suite is 210/210 green including |
Fixes #3225.
Bug
FormatTimeSys()renders asteady_clocktimestamp as wall-clock time, but it combined whole-second wall time from::time()with the sub-second part ofsteady_clock::now(). Those clocks have unrelated sub-second phases (steady counts from an arbitrary epoch), so near a second boundary the same timestamp rendered one second apart between calls — the ±1s discrepancy in the issue. Per-call re-sampling of two clocks non-atomically also adds ~1µs jitter.Fix
Map the timestamp through a single steady↔wall reference pair, captured once at load time, in one consistent microsecond domain. A given timestamp now always formats to exactly the same string. The arithmetic is factored into a pure, testable overload
FormatTimeSys(target_us, steady_now_us, wall_now_us). This touches only the[SYST]logging/trace formatter — not the transport path.Tradeoff (for maintainer review)
This caches the steady↔wall offset for stability. If the wall clock is NTP-stepped mid-run,
[SYST]times drift by the step amount but stay internally consistent. The alternative — live re-tracking with only the flicker removed — is also reasonable; happy to switch to that if you prefer. Flagging since it's your issue and touches a utility.Verification
Sync.FormatTimeSysStablesweeps the reference across misaligned steady/wall second boundaries and asserts a fixed timestamp renders identically — fails on the old arithmetic, passes with the fix.--gtest_repeat=200onSync.FormatTime*→ 200/200 (also removes a latent flake in the existing back-to-back-equality test).-DENABLE_UNITTESTS=ON, no new warnings. DCO sign-off included.