From 521aab0da2b338fe337744f3b0bc241bd951aa6f Mon Sep 17 00:00:00 2001 From: Mike German Date: Mon, 6 Jul 2026 22:49:49 -0400 Subject: [PATCH 1/2] [core] Fix FormatTimeSys rendering the same timestamp inconsistently 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 #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) Signed-off-by: Mike German --- srtcore/sync.cpp | 57 +++++++++++++++++++++++++++++++++++++--------- srtcore/sync.h | 8 +++++++ test/test_sync.cpp | 38 +++++++++++++++++++++++++++++++ 3 files changed, 92 insertions(+), 11 deletions(-) diff --git a/srtcore/sync.cpp b/srtcore/sync.cpp index ff16a7146..71f5a29a0 100644 --- a/srtcore/sync.cpp +++ b/srtcore/sync.cpp @@ -60,23 +60,58 @@ std::string FormatTime(const steady_clock::time_point& timestamp) return out.str(); } -std::string FormatTimeSys(const steady_clock::time_point& timestamp) -{ - const time_t now_s = ::time(NULL); // get current time in seconds - const steady_clock::time_point now_timestamp = steady_clock::now(); - const int64_t delta_us = count_microseconds(timestamp - now_timestamp); - const int64_t delta_s = - static_cast(floor((static_cast(count_microseconds(now_timestamp.time_since_epoch()) % 1000000) + delta_us) / 1000000.0)); - const time_t tt = now_s + delta_s; - struct tm tm = SysLocalTime(tt); // in seconds - char tmp_buf[512]; +std::string FormatTimeSys(int64_t target_us, int64_t steady_now_us, int64_t wall_now_us) +{ + // Map the steady-clock timestamp into the wall clock using a single, + // microsecond-precision reference pair (steady_now_us, wall_now_us) sampled + // at the same instant. The previous implementation combined whole-second + // wall time (::time) with sub-second steady time, whose sub-second phases + // are unrelated; near a second boundary this made the very same timestamp + // render with a +/-1 second difference between calls (see issue #3225). + const int64_t target_wall_us = wall_now_us + (target_us - steady_now_us); + const time_t tt = static_cast(target_wall_us / 1000000); + const int64_t subsec_us = target_wall_us % 1000000; + + struct tm tm = SysLocalTime(tt); // in seconds + char tmp_buf[512]; strftime(tmp_buf, 512, "%X.", &tm); ostringstream out; - out << tmp_buf << setfill('0') << setw(6) << (count_microseconds(timestamp.time_since_epoch()) % 1000000) << " [SYST]"; + out << tmp_buf << setfill('0') << setw(6) << subsec_us << " [SYST]"; return out.str(); } +namespace +{ + // A single steady<->wall reference pair, sampled once at load time. Using a + // fixed reference (rather than re-sampling on every call) guarantees that the + // same steady timestamp always renders to exactly the same wall-clock string. + // Re-sampling would reintroduce jitter: gettimeofday() and steady_clock::now() + // are read non-atomically, so their offset wobbles by ~1us between calls, which + // is enough to flip the last printed digit (and, in the old code, a whole + // second near a boundary - see issue #3225). The reference is initialized + // before main(), so no locking is needed. + struct SysClockReference + { + int64_t steady_us; + int64_t wall_us; + SysClockReference() + { + timeval tv; + gettimeofday(&tv, NULL); + wall_us = static_cast(tv.tv_sec) * 1000000 + tv.tv_usec; + steady_us = count_microseconds(steady_clock::now().time_since_epoch()); + } + }; + const SysClockReference s_sysClockRef; +} + +std::string FormatTimeSys(const steady_clock::time_point& timestamp) +{ + const int64_t target_us = count_microseconds(timestamp.time_since_epoch()); + return FormatTimeSys(target_us, s_sysClockRef.steady_us, s_sysClockRef.wall_us); +} + #ifdef ENABLE_STDCXX_SYNC bool StartThread(CThread& th, ThreadFunc&& f, void* args, const string& name) diff --git a/srtcore/sync.h b/srtcore/sync.h index a5ac6d684..710064106 100644 --- a/srtcore/sync.h +++ b/srtcore/sync.h @@ -879,6 +879,14 @@ std::string FormatTime(const steady_clock::time_point& time); /// @returns a string with a formatted time representation std::string FormatTimeSys(const steady_clock::time_point& time); +/// Core of FormatTimeSys with the "now" reference passed explicitly, so the +/// steady->wall mapping is pure and can be unit tested deterministically. +/// @param [in] target_us steady-clock timestamp to format (microseconds since epoch) +/// @param [in] steady_now_us steady clock "now" (microseconds since epoch) +/// @param [in] wall_now_us wall clock "now" (microseconds since Unix epoch), same instant +/// @returns a string with a formatted time representation +std::string FormatTimeSys(int64_t target_us, int64_t steady_now_us, int64_t wall_now_us); + enum eDurationUnit {DUNIT_S, DUNIT_MS, DUNIT_US}; template diff --git a/test/test_sync.cpp b/test/test_sync.cpp index ffbbc2b28..d42f4921d 100644 --- a/test/test_sync.cpp +++ b/test/test_sync.cpp @@ -793,4 +793,42 @@ TEST(Sync, FormatTimeSys) EXPECT_TRUE(time1 == time2); } + +// Regression test for issue #3225: FormatTimeSys must render the very same +// steady-clock timestamp identically regardless of when it is called. The old +// implementation mixed whole-second wall time with sub-second steady time, whose +// sub-second phases are unrelated, so near a second boundary the same timestamp +// could render 1 second apart. This test drives the pure (target, steady_now, +// wall_now) core across a range of "now" samples that repeatedly cross both the +// steady and the wall second boundaries (using deliberately different sub-second +// phases for the two clocks), and asserts the output is stable. +TEST(Sync, FormatTimeSysStable) +{ + // Fixed target timestamp to format (steady clock, microseconds since epoch). + const int64_t target_us = 42 * 1000000 + 676394; + + // Constant offset between the wall clock and the steady clock. Crucially it has + // a non-integer-second (0.5 s) sub-second component: a real steady clock counts + // from an arbitrary epoch (e.g. boot), so its sub-second phase does not line up + // with the wall clock's. That misalignment is exactly what made the old code + // (which mixed whole-second wall time with sub-second steady time) render the + // same timestamp 1 second apart near a boundary. + const int64_t clock_offset_us = INT64_C(1700000000) * 1000000 + 500000; // .5 s phase + + std::string reference; + // Sweep "now" across >2 seconds in 50 ms steps, starting off a second boundary + // so both clocks' boundaries are crossed while their phases stay misaligned. + for (int64_t step_us = 123456; step_us <= 123456 + 2500000; step_us += 50000) + { + const int64_t steady_now_us = step_us; + const int64_t wall_now_us = steady_now_us + clock_offset_us; + const std::string formatted = FormatTimeSys(target_us, steady_now_us, wall_now_us); + + if (reference.empty()) + reference = formatted; + else + EXPECT_EQ(formatted, reference) + << "FormatTimeSys is unstable for a fixed timestamp (steady_now_us=" << steady_now_us << ")"; + } +} #endif From b075ca8b3845af43dcb996096cb35afe92e917dc Mon Sep 17 00:00:00 2001 From: Mike German Date: Mon, 27 Jul 2026 22:45:25 -0400 Subject: [PATCH 2/2] [core] Reshape FormatTimeSys test seam per review 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 Co-Authored-By: Claude Fable 5 --- srtcore/sync.cpp | 87 ++++++++++++++++++++++++---------------------- srtcore/sync.h | 31 +++++++++++++---- test/test_sync.cpp | 13 ++++--- 3 files changed, 79 insertions(+), 52 deletions(-) diff --git a/srtcore/sync.cpp b/srtcore/sync.cpp index 71f5a29a0..f8c053874 100644 --- a/srtcore/sync.cpp +++ b/srtcore/sync.cpp @@ -60,56 +60,61 @@ std::string FormatTime(const steady_clock::time_point& timestamp) return out.str(); } -std::string FormatTimeSys(int64_t target_us, int64_t steady_now_us, int64_t wall_now_us) -{ - // Map the steady-clock timestamp into the wall clock using a single, - // microsecond-precision reference pair (steady_now_us, wall_now_us) sampled - // at the same instant. The previous implementation combined whole-second - // wall time (::time) with sub-second steady time, whose sub-second phases - // are unrelated; near a second boundary this made the very same timestamp - // render with a +/-1 second difference between calls (see issue #3225). - const int64_t target_wall_us = wall_now_us + (target_us - steady_now_us); - const time_t tt = static_cast(target_wall_us / 1000000); - const int64_t subsec_us = target_wall_us % 1000000; - - struct tm tm = SysLocalTime(tt); // in seconds - char tmp_buf[512]; - strftime(tmp_buf, 512, "%X.", &tm); - - ostringstream out; - out << tmp_buf << setfill('0') << setw(6) << subsec_us << " [SYST]"; - return out.str(); +SysClockReference::SysClockReference() +{ + timeval tv; + gettimeofday(&tv, NULL); + wall_us = static_cast(tv.tv_sec) * 1000000 + tv.tv_usec; + steady_us = count_microseconds(steady_clock::now().time_since_epoch()); } namespace { - // A single steady<->wall reference pair, sampled once at load time. Using a - // fixed reference (rather than re-sampling on every call) guarantees that the - // same steady timestamp always renders to exactly the same wall-clock string. - // Re-sampling would reintroduce jitter: gettimeofday() and steady_clock::now() - // are read non-atomically, so their offset wobbles by ~1us between calls, which - // is enough to flip the last printed digit (and, in the old code, a whole - // second near a boundary - see issue #3225). The reference is initialized - // before main(), so no locking is needed. - struct SysClockReference + // Map a steady clock timestamp into the wall clock domain (microseconds + // since the Unix epoch) using a single, microsecond-precision clock + // reference sampled at one instant. The previous implementation combined + // whole-second wall time (::time) with sub-second steady time, whose + // sub-second phases are unrelated; near a second boundary this made the + // very same timestamp render with a +/-1 second difference between calls + // (see issue #3225). + int64_t ToSysTimeMicroseconds(const steady_clock::time_point& timestamp, const SysClockReference& rf) + { + return rf.wall_us + (count_microseconds(timestamp.time_since_epoch()) - rf.steady_us); + } + + // Format a wall clock time (microseconds since the Unix epoch) as + // HH:MM:SS.us [SYST]. + std::string FormatSysTimeMicroseconds(int64_t wall_us) { - int64_t steady_us; - int64_t wall_us; - SysClockReference() - { - timeval tv; - gettimeofday(&tv, NULL); - wall_us = static_cast(tv.tv_sec) * 1000000 + tv.tv_usec; - steady_us = count_microseconds(steady_clock::now().time_since_epoch()); - } - }; - const SysClockReference s_sysClockRef; + const time_t tt = static_cast(wall_us / 1000000); + const int64_t subsec_us = wall_us % 1000000; + + struct tm tm = SysLocalTime(tt); // in seconds + char tmp_buf[512]; + strftime(tmp_buf, 512, "%X.", &tm); + + ostringstream out; + out << tmp_buf << setfill('0') << setw(6) << subsec_us << " [SYST]"; + return out.str(); + } +} + +std::string FormatTimeSysInternal(const steady_clock::time_point& timestamp, const SysClockReference& rf) +{ + return FormatSysTimeMicroseconds(ToSysTimeMicroseconds(timestamp, rf)); } std::string FormatTimeSys(const steady_clock::time_point& timestamp) { - const int64_t target_us = count_microseconds(timestamp.time_since_epoch()); - return FormatTimeSys(target_us, s_sysClockRef.steady_us, s_sysClockRef.wall_us); + // A single clock reference, sampled once on first use. Using a fixed + // reference (rather than re-sampling on every call) guarantees that the + // same steady timestamp always renders to exactly the same wall-clock + // string. Re-sampling would reintroduce jitter: gettimeofday() and + // steady_clock::now() are read non-atomically, so their offset wobbles by + // ~1us between calls, which is enough to flip the last printed digit (and, + // in the old code, a whole second near a boundary - see issue #3225). + static const SysClockReference s_sys_clock_ref; + return FormatTimeSysInternal(timestamp, s_sys_clock_ref); } diff --git a/srtcore/sync.h b/srtcore/sync.h index 710064106..f166ac24a 100644 --- a/srtcore/sync.h +++ b/srtcore/sync.h @@ -879,13 +879,32 @@ std::string FormatTime(const steady_clock::time_point& time); /// @returns a string with a formatted time representation std::string FormatTimeSys(const steady_clock::time_point& time); -/// Core of FormatTimeSys with the "now" reference passed explicitly, so the -/// steady->wall mapping is pure and can be unit tested deterministically. -/// @param [in] target_us steady-clock timestamp to format (microseconds since epoch) -/// @param [in] steady_now_us steady clock "now" (microseconds since epoch) -/// @param [in] wall_now_us wall clock "now" (microseconds since Unix epoch), same instant +// Exposed for testing purposes only. Not intended for any other use. + +/// A steady<->wall clock reference: a sample of both clocks taken at the same +/// instant, used to map steady clock timestamps into the wall clock domain. +struct SysClockReference +{ + int64_t steady_us; ///< steady clock sample (microseconds since its epoch) + int64_t wall_us; ///< wall clock sample at the same instant (microseconds since Unix epoch) + + /// Samples both clocks at (nearly) the same instant. + SysClockReference(); + + SysClockReference(int64_t steady, int64_t wall) + : steady_us(steady) + , wall_us(wall) + { + } +}; + +/// Internal version of FormatTimeSys with the clock reference passed +/// explicitly, so the steady->wall mapping is pure and can be unit tested +/// deterministically. Exposed for testing purposes only. +/// @param [in] time steady clock timepoint to format +/// @param [in] rf steady<->wall clock reference to map the timepoint with /// @returns a string with a formatted time representation -std::string FormatTimeSys(int64_t target_us, int64_t steady_now_us, int64_t wall_now_us); +std::string FormatTimeSysInternal(const steady_clock::time_point& time, const SysClockReference& rf); enum eDurationUnit {DUNIT_S, DUNIT_MS, DUNIT_US}; diff --git a/test/test_sync.cpp b/test/test_sync.cpp index d42f4921d..76d8d68ea 100644 --- a/test/test_sync.cpp +++ b/test/test_sync.cpp @@ -798,14 +798,16 @@ TEST(Sync, FormatTimeSys) // steady-clock timestamp identically regardless of when it is called. The old // implementation mixed whole-second wall time with sub-second steady time, whose // sub-second phases are unrelated, so near a second boundary the same timestamp -// could render 1 second apart. This test drives the pure (target, steady_now, -// wall_now) core across a range of "now" samples that repeatedly cross both the -// steady and the wall second boundaries (using deliberately different sub-second -// phases for the two clocks), and asserts the output is stable. +// could render 1 second apart. This test drives FormatTimeSysInternal with +// explicit clock references across a range of "now" samples that repeatedly +// cross both the steady and the wall second boundaries (using deliberately +// different sub-second phases for the two clocks), and asserts the output is +// stable. TEST(Sync, FormatTimeSysStable) { // Fixed target timestamp to format (steady clock, microseconds since epoch). const int64_t target_us = 42 * 1000000 + 676394; + const steady_clock::time_point target = steady_clock::time_point() + microseconds_from(target_us); // Constant offset between the wall clock and the steady clock. Crucially it has // a non-integer-second (0.5 s) sub-second component: a real steady clock counts @@ -822,7 +824,8 @@ TEST(Sync, FormatTimeSysStable) { const int64_t steady_now_us = step_us; const int64_t wall_now_us = steady_now_us + clock_offset_us; - const std::string formatted = FormatTimeSys(target_us, steady_now_us, wall_now_us); + const SysClockReference rf(steady_now_us, wall_now_us); + const std::string formatted = FormatTimeSysInternal(target, rf); if (reference.empty()) reference = formatted;