diff --git a/srtcore/sync.cpp b/srtcore/sync.cpp index ff16a7146..f8c053874 100644 --- a/srtcore/sync.cpp +++ b/srtcore/sync.cpp @@ -60,21 +60,61 @@ std::string FormatTime(const steady_clock::time_point& timestamp) return out.str(); } -std::string FormatTimeSys(const steady_clock::time_point& timestamp) +SysClockReference::SysClockReference() { - 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]; - strftime(tmp_buf, 512, "%X.", &tm); + 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()); +} - ostringstream out; - out << tmp_buf << setfill('0') << setw(6) << (count_microseconds(timestamp.time_since_epoch()) % 1000000) << " [SYST]"; - return out.str(); +namespace +{ + // 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) + { + 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) +{ + // 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 a5ac6d684..f166ac24a 100644 --- a/srtcore/sync.h +++ b/srtcore/sync.h @@ -879,6 +879,33 @@ 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); +// 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 FormatTimeSysInternal(const steady_clock::time_point& time, const SysClockReference& rf); + enum eDurationUnit {DUNIT_S, DUNIT_MS, DUNIT_US}; template diff --git a/test/test_sync.cpp b/test/test_sync.cpp index ffbbc2b28..76d8d68ea 100644 --- a/test/test_sync.cpp +++ b/test/test_sync.cpp @@ -793,4 +793,45 @@ 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 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 + // 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 SysClockReference rf(steady_now_us, wall_now_us); + const std::string formatted = FormatTimeSysInternal(target, rf); + + if (reference.empty()) + reference = formatted; + else + EXPECT_EQ(formatted, reference) + << "FormatTimeSys is unstable for a fixed timestamp (steady_now_us=" << steady_now_us << ")"; + } +} #endif