incorrect decoded timestamp

[Ziemien]

• clang 15.0.7
• decoded timestamp in human readable form is incorrect
• latest commit 4cd8f78

2078-02-08 05:03:29.555899122 1706600004780364437 INFO Hello1 World! (main.cxx:8)
2078-02-08 05:03:29.555902123 1706600004780367438 WARN Testing again (main.cxx:10)

$ date
Tue Jan 30 03:49:03 PM HKT 2024

• the actual %r recorded timestamp is correct but then thee %d results in a year being 2078...; also tested on server with UTC timezone - same issue

• to reproduce basic demo example either Text output or a file output results in wrong timestamp

[Ziemien]

The problem seems to be with Time.hpp ClockSync object with ClockValue is initialized with microseconds instead of nanoseconds, .nsSinceEpoch is later correctly adjusted to nanoseconds

Issue seems to come up later with bread in https://github.com/morganstanley/binlog/blob/main/include/binlog/Time.cpp#L22, clockToNsSinceEpoch on line 22 compares microseconds to nanoseconds which results in bogus diffValue

binlog::clockNow() returns time in nanoseconds, which is what is being serialized onto the write queue. Fixing the systemClockSync to return ClockTime in nanoseconds by using duraction cast seems to fix the issue.

We use libcxx with clang and based on the src code it does seem to return time_point in microseconds https://github.com/llvm-mirror/libcxx/blob/master/src/chrono.cpp, also quite interesting based on compilation flag in GCC the time can be either nanoseconds or microseconds https://github.com/gcc-mirror/gcc/blob/master/libstdc++-v3/src/c++11/chrono.cc#L52 - then duration cast seems to be appropriate ?

-- edit

I do confirm that there is no problem on GCC 11.4.1 and indeed GCC returns time in nanoseconds where the LLVM's libcxx returns microseconds

[erenon]

Thanks for reporting! Do you use macOS? A duration cast the right place would be appropriate probably.

[Ziemien]

We use MacOS and RHEL 9 hence LLVM. Tested with GCC as edited on the previous post and indeed implementation of the standard library is causing the issues.

[erenon]

Something is unclear to me. ClockSync:

struct ClockSync
{
  static constexpr std::uint64_t Tag = std::uint64_t(-3);

  std::uint64_t clockValue = {};     /**< Clock when time is `nsSinceEpoch` */
  std::uint64_t clockFrequency = {}; /**< Number of clock ticks in a second */

  std::uint64_t nsSinceEpoch = {};   /**< Nanoseconds since UNIX epoch in UTC, no leap seconds */
  std::int32_t tzOffset = {};        /**< Time zone offset from UTC in seconds */
  std::string tzName;                /**< Time zone name */
};

clockValue can be anything sensible, it is not required to be ns. The doc above it clearly explains how one can compute the actual time using the frequency and the anchor point (nsSinceEpoch).

Also in PrettyPrinter.cpp:

    BrokenDownTime bdt{};
    const std::chrono::nanoseconds sinceEpoch = clockToNsSinceEpoch(*_clockSync, clockValue);
    nsSinceEpochToBrokenDownTimeUTC(sinceEpoch, bdt);
    printTime(out, bdt, 0, "UTC");

The clock value should be converted to ns here. Is the frequency in the ClockSync wrong in you case?

[Ziemien]

I mean I am not an expert of the code base; in current code clockFrequency seems to assume it has to be in nanoseconds as it's plainly hardcoded (Time.hpp:L101):

// on linux, clock_gettime is used directly
  #ifdef __linux__
    const uint64_t frequency = 1'000'000'000; // nanoseconds
  #else
    const uint64_t frequency = std::uint64_t(Clock::period::den);
  #endif

My intention with the PR was not to take other clocks / resolutions into account but to make the logic consistent regardless of what the system clock returns; given clock returns a time_point then the duration cast seems to fix the issue; if the code wants the nanoseconds frequency (given the ifdef) then the duration cast would be the easiest fix?

[erenon]

During logging, the Clock value is logged unchanged. If the ClockSync doesn't have such a clock value, we'll not be able to interpret it in bread. Let's understand the issue better first, I was jumping to conclusions before. I'm unable to repro this neither on linux (g++ 11.4) nor macOS (clang++ 15.0). Which platform+compiler combination gives you this issue? On the affected platform, can you print a ClockValue instance with a debugger, that was created by systemClockSync?

[Ziemien]

Indeed the clock value is logged unchanged in nanoseconds.

-> ClockValue in libcxx 15.0.7 (we have a custom build, not using apple) is returned in microseconds - 1706604819245322
-> , in gcc 11.4 1706606658334682026ns

[erenon]

I suppose on RHEL it works correctly, on macOS it does not. What's the clock frequency of the ClockSync on the broken platform?

[Ziemien]

It does not work correctly on RHEL, the clock frequency it's the same as if def. All reporting on this ticket is used on RHEL 9.2. I haven't tried it on MacOS

https://github.com/llvm-mirror/libcxx/blob/master/src/chrono.cpp#L83 - is clearly visible that it returns in microseconds

[erenon]

thanks for pointing this out. sad. In this case, instead of Clock::now() on line 72, clockNow() should be used (then converted to a duration). The actual bug here is that in systemClockSync Clock::now() is used on every platform, while elswhere clockNow(), that uses clock_gettime explicitly on linux.

[erenon]

@Ziemien please see #173. If it works for you, I'll arrange merging it. thanks!

[Ziemien]

it does not seem to compile (Clang 15.0.7)

include/binlog/Time.hpp:102:23: error: no matching conversion for functional-style cast from 'const std::chrono::nanoseconds' (aka 'const duration<long long, ratio<1LL, 1000000000LL>>') to 'Clock::time_point' (aka 'time_point<std::chrono::system_clock>')
  const auto now_tp = Clock::time_point(since_epoch);

[erenon]

Thanks for checking. Reproduced locally and fixed it. Please try again.