Test CLOCK_MONOTONIC/CLOCK_MONOTONIC_RAW/rdtsc monotonicity

test-clocks-monotonicity.cpp

#include <atomic>
#include <bits/types/clockid_t.h>
#include <cstdint>
#include <cstdlib>
#include <ctime>
#include <cerrno>
#include <iostream>
#include <list>
#include <random>
#include <sched.h>
#include <stdexcept>
#include <thread>
#include <utility>

#define THREADS 1
#define VERBOSE_ERROR (THREADS==1)
#define GLOBAL_CLOCK_COUNTER (THREADS>100)
#define CLOCK_ITERATIONS 1'000ULL
/// Run via unshare -T, since docker does not suppor time ns [1].
///   [1]: https://github.com/moby/moby/issues/39163
#define NTP_THREAD_SYSTEMD 0
#define NTP_THREAD_CHRONYD 1
#define SCHED_YIELD (THREADS==1 || GLOBAL_CLOCK_COUNTER==0)

#define NSEC_PER_SEC (1000000000ULL)
#define NSEC_PER_MSEC (1000000LL)

__inline__ uint64_t rdtsc(void)
{
    uint32_t lo, hi;
    __asm__ __volatile__ (      // serialize
    "xorl %%eax,%%eax \n        cpuid"
    ::: "%rax", "%rbx", "%rcx", "%rdx");
    /* We cannot use "=A", since this would use %rax on x86_64 and return only the lower 32bits of the TSC */
    __asm__ __volatile__ ("rdtsc" : "=a" (lo), "=d" (hi));
    return (uint64_t)hi << 32 | lo;
}

timespec _clock_gettime(clockid_t clk)
{
    timespec ts;
    if (clock_gettime(clk, &ts))
    {
        perror("clock_gettime");
        throw std::runtime_error("clock_gettime");
    }
    return ts;
}

uint64_t now_ns(clockid_t clock)
{
    struct timespec ts = _clock_gettime(clock);
    return ts.tv_sec * (uint64_t)1e9 + ts.tv_nsec;
}

template <class F, class ... Args>
uint64_t elapsed_ns(clockid_t clock, const F & f, Args && ... args)
{
    uint64_t start = now_ns(clock);
    f(std::forward<Args>(args)...);
    uint64_t end = now_ns(clock);
    return end - start;
}


template <class F, class ... Args>
auto run(const F & f, Args && ... args)
{
    std::atomic_bool stopped = false;

    /// FIXME: split for systemd vs chronyd
#if GLOBAL_CLOCK_COUNTER
    std::atomic<uint64_t> counter = 0;
    std::atomic<unsigned> cpu = -1;
#else
    thread_local uint64_t counter = 0;
    thread_local unsigned cpu = -1;
#endif
    std::atomic<uint64_t> errors = 0;

#if NTP_THREAD_SYSTEMD
    std::thread ntp_systemd([&]() {
        size_t i = 0;
        while (!stopped.load(std::memory_order_relaxed)) {
            timex tmx{};
            tmx.modes = ADJ_STATUS | ADJ_NANO | ADJ_OFFSET | ADJ_TIMECONST | ADJ_MAXERROR | ADJ_ESTERROR;
            // tmx.status = STA_PLL | STA_NANO | STA_MODE;
            tmx.status = STA_PLL | STA_NANO;
            if (rand() % 2)
                tmx.offset = -rand()%500 * NSEC_PER_MSEC;
            else
                tmx.offset = rand()%500 * NSEC_PER_MSEC;
            tmx.constant = 7;

            timespec old_ts = _clock_gettime(CLOCK_REALTIME);
            uint64_t took_ns = elapsed_ns(CLOCK_MONOTONIC_RAW, [&]() {
                /// NOTE: clock_adjtime(CLOCK_REALTIME) is the same as adjtimex()/ntp_adjtime()
                if (clock_adjtime(CLOCK_REALTIME, &tmx))
                {
                    perror("clock_adjtime");
                    throw std::runtime_error("clock_adjtime");
                }
            });
            timespec now_ts = _clock_gettime(CLOCK_REALTIME);

            if (i++ == 0)
                fprintf(stderr,
                    "  status       : %04i %s\n"
                    "  time was     : %li.%03lli\n"
                    "  adjtime time : %li.%03lli\n"
                    "  time now     : %li.%03lli\n"
                    "  adjtime took : %li ns\n"
                    "  constant     : %li\n"
                    "  offset       : %+.3f sec\n"
                    "  freq offset  : %+li (%+li ppm)\n",
                    tmx.status, tmx.status & STA_UNSYNC ? "unsync" : "sync",
                    old_ts.tv_sec, old_ts.tv_nsec / NSEC_PER_SEC,
                    tmx.time.tv_sec, tmx.time.tv_usec / NSEC_PER_MSEC,
                    now_ts.tv_sec, now_ts.tv_nsec / NSEC_PER_SEC,
                    took_ns,
                    tmx.constant,
                    (double)tmx.offset / NSEC_PER_SEC,
                    tmx.freq, tmx.freq / 65536);
        }
    });
#endif
#if NTP_THREAD_CHRONYD
    std::default_random_engine generator;

    std::thread ntp_chronyd([&]() {
        size_t i = 0;

        /// Set frequency offset from buf.freq.  Since Linux 2.6.26, the supplied value is clamped to the range (-32768000, +32768000)
        std::normal_distribution<double> freq_distribution(-32768000, +32768000);
        /* std::normal_distribution<double> tick_distribution(9999, 10001); */

        while (!stopped.load(std::memory_order_relaxed)) {
            timex tmx{};
            /* tmx.modes = ADJ_FREQUENCY|ADJ_TICK; */
            /* tmx.modes = ADJ_STATUS | ADJ_NANO | ADJ_OFFSET | ADJ_TIMECONST | ADJ_MAXERROR | ADJ_ESTERROR; */
            tmx.modes = ADJ_STATUS|ADJ_FREQUENCY;
            /* if (rand() % 2) */
            /*     tmx.status = STA_PLL | STA_NANO; */
            /* tmx.offset = (rand() % 2 ? -1 : 1)*rand()%500 * NSEC_PER_MSEC; */
            tmx.freq = freq_distribution(generator);
            /* tmx.tick = tick_distribution(generator); */
            tmx.constant = 7;

            timespec old_ts = _clock_gettime(CLOCK_REALTIME);
            uint64_t took_ns = elapsed_ns(CLOCK_MONOTONIC_RAW, [&]() {
                /// NOTE: clock_adjtime(CLOCK_REALTIME) is the same as adjtimex()/ntp_adjtime()
                if (clock_adjtime(CLOCK_REALTIME, &tmx))
                {
                    perror("clock_adjtime");
                    throw std::runtime_error("clock_adjtime");
                }
            });
            timespec now_ts = _clock_gettime(CLOCK_REALTIME);

            fprintf(stderr,
                "status: %04i %s, "
                "time was: %li.%03lli, "
                "adjtime time: %li.%03lli, "
                "time now: %li.%03lli, "
                "adjtime took: %li ns, "
                "offset: %+.3f sec, "
                "freq offset: %+li (%+li ppm)\n",
                tmx.status, tmx.status & STA_UNSYNC ? "unsync" : "sync",
                old_ts.tv_sec, old_ts.tv_nsec / NSEC_PER_SEC,
                tmx.time.tv_sec, tmx.time.tv_usec / NSEC_PER_MSEC,
                now_ts.tv_sec, now_ts.tv_nsec / NSEC_PER_SEC,
                took_ns,
                (double)tmx.offset / NSEC_PER_SEC,
                tmx.freq, tmx.freq / 65536);
        }
    });
#endif

    std::list<std::thread> threads(THREADS);
    for (auto & thread : threads)
    {
        thread = std::thread([&]() {
            for (size_t i = 0; i < CLOCK_ITERATIONS; ++i)
            {
#if SCHED_YIELD
                if (!(rand()%10000))
                    sched_yield();
#endif
                /// NOTE: racy, but should work
                unsigned old_cpu = cpu;
                uint64_t old_counter = counter;
                counter = f(std::forward<Args>(args)...);
                if (getcpu(&cpu, NULL))
                {
                    perror("getcpu");
                    break;
                }
                if (old_counter > counter)
                {
#if VERBOSE_ERROR
                    if (errors < 10)
                        fprintf(stderr, "ERROR: old_counter = %lu, new_counter = %lu, old CPU = %u, CPU = %u\n", old_counter, counter, old_cpu, cpu);
#endif
                    ++errors;
                }
            }
        });
    }

    for (auto & thread : threads)
        thread.join();

    stopped = true;
#if NTP_THREAD_SYSTEMD
    ntp_systemd.join();
#endif
#if NTP_THREAD_CHRONYD
    ntp_chronyd.join();
#endif

    return errors.load();
}


int main()
{
    std::cout << "THREADS = " << THREADS << "\n";
    std::cout << "GLOBAL_CLOCK_COUNTER = " << GLOBAL_CLOCK_COUNTER << "\n";
    std::cout << "CLOCK_ITERATIONS = " << CLOCK_ITERATIONS << "\n";
    std::cout << "NTP_THREAD_SYSTEMD = " << NTP_THREAD_SYSTEMD << "\n";
    std::cout << "NTP_THREAD_CHRONYD = " << NTP_THREAD_CHRONYD << "\n";
    std::cout << "SCHED_YIELD = " << SCHED_YIELD << "\n";

    uint64_t overall_errors = 0;
    {
        std::cout << "rdtsc: ";
        auto errors = run(rdtsc);
        if (errors)
            std::cout << "errors: " << errors << "\n";
        else
            std::cout << "OK\n";
        overall_errors += errors;
    }

    {
        std::cout << "CLOCK_MONOTONIC: ";
        auto errors = run(now_ns, CLOCK_MONOTONIC);
        if (errors)
            std::cout << "errors: " << errors << "\n";
        else
            std::cout << "OK\n";
        overall_errors += errors;
    }

    {
        std::cout << "CLOCK_MONOTONIC_COARSE: ";
        auto errors = run(now_ns, CLOCK_MONOTONIC_COARSE);
        if (errors)
            std::cout << "errors: " << errors << "\n";
        else
            std::cout << "OK\n";
        overall_errors += errors;
    }

    {
        std::cout << "CLOCK_MONOTONIC_RAW: ";
        auto errors = run(now_ns, CLOCK_MONOTONIC_RAW);
        if (errors)
            std::cout << "errors: " << errors << "\n";
        else
            std::cout << "OK\n";
        overall_errors += errors;
    }

    return overall_errors > 0 ? EXIT_FAILURE : EXIT_SUCCESS;
}

$ clang++ -O3 -o /tmp/test-clocks /tmp/test-clocks.cpp -static && /tmp/test-clocks
rdtsc: errors: 43095
CLOCK_MONOTONIC: errors: 28451
CLOCK_MONOTONIC_RAW: errors: 2807

$ nice -n1000 /tmp/test-clocks
THREADS = 1000
GLOBAL_CLOCK_COUNTER = 0
CLOCK_ITERATIONS = 100000
NTP_THREAD = 0
SCHED_YIELD = 1
rdtsc: OK
CLOCK_MONOTONIC: OK
CLOCK_MONOTONIC_RAW: OK

$ sudo unshare -T /tmp/test-clocks
THREADS = 10
GLOBAL_CLOCK_COUNTER = 1
CLOCK_ITERATIONS = 1000000
NTP_THREAD = 0
SCHED_YIELD = 0
rdtsc: errors: 78814
CLOCK_MONOTONIC: errors: 86226
CLOCK_MONOTONIC_COARSE: errors: 6
CLOCK_MONOTONIC_RAW: errors: 13727

Interesting, CLOCK_MONOTONIC_COARSE is more stable in case of multiple threads

I've managed to fail the CLOCK_MONOTONIC_COARSE with clock_adjtime!

$ yes | xargs -I -- sh -c '/tmp/test-clocks || exit 255'
...
THREADS = 1
GLOBAL_CLOCK_COUNTER = 0
CLOCK_ITERATIONS = 1000000
NTP_THREAD = 1
SCHED_YIELD = 1
  status       : 8193 sync
  time was     : 1720698382.000
  adjtime time : 1720698382.476
  time now     : 1720698382.000
  adjtime took : 4585 ns
  constant     : 7
  offset       : -0.386 sec
  freq offset  : +7755715 (+118 ppm)
rdtsc: OK
  status       : 8193 sync
  time was     : 1720698384.000
  adjtime time : 1720698384.592
  time now     : 1720698384.000
  adjtime took : 3881 ns
  constant     : 7
  offset       : -0.453 sec
  freq offset  : +7747480 (+118 ppm)
CLOCK_MONOTONIC: OK
  status       : 8193 sync
  time was     : 1720698384.000
  adjtime time : 1720698384.715
  time now     : 1720698384.000
  adjtime took : 3304 ns
  constant     : 7
  offset       : -0.302 sec
  freq offset  : +7747480 (+118 ppm)
CLOCK_MONOTONIC_COARSE: errors: 1
  status       : 8193 sync
  time was     : 1720698384.000
  adjtime time : 1720698384.843
  time now     : 1720698384.000
  adjtime took : 2745 ns
  constant     : 7
  offset       : -0.156 sec
  freq offset  : +3836719 (+58 ppm)
CLOCK_MONOTONIC_RAW: OK
xargs: sh: exited with status 255; aborting

P.S. from now on, all results had been done on AWS, m5d.4xlarge:

• 6.5.0-1022-aws kernel
• hypervizor - xen (aws ec2 describe-instances --instance-ids X --query "Reservations[].Instances[].Hypervisor")
• ubuntu 22.04

root@ip-172-31-29-231:/home/ubuntu# /tmp/clock_times 1
CLOCK_REALTIME : 1720701066.421 (19915 days + 12h 31m  6s)
     resolution:          0.000000001
CLOCK_TAI      : 1720701103.421 (19915 days + 12h 31m 43s)
     resolution:          0.000000001
CLOCK_MONOTONIC:       6226.604 ( 1h 43m 46s)
     resolution:          0.000000001
CLOCK_MONOTONIC_COARSE:       6226.601 ( 1h 43m 46s)
     resolution:          0.004000000
CLOCK_BOOTTIME :       6226.605 ( 1h 43m 46s)
     resolution:          0.000000001

One more failure with details:

THREADS = 1
GLOBAL_CLOCK_COUNTER = 0
CLOCK_ITERATIONS = 1000000
NTP_THREAD = 1
SCHED_YIELD = 1
  status       : 8193 sync
  time was     : 1720702927.000
  adjtime time : 1720702927.847
  time now     : 1720702927.000
  adjtime took : 4773 ns
  constant     : 7
  offset       : -0.386 sec
  freq offset  : +2345712 (+35 ppm)
rdtsc: OK
  status       : 8193 sync
  time was     : 1720702929.000
  adjtime time : 1720702929.737
  time now     : 1720702929.000
  adjtime took : 4094 ns
  constant     : 7
  offset       : +0.260 sec
  freq offset  : +2341056 (+35 ppm)
CLOCK_MONOTONIC: OK
  status       : 8193 sync
  time was     : 1720702929.000
  adjtime time : 1720702929.876
  time now     : 1720702929.000
  adjtime took : 3729 ns
  constant     : 7
  offset       : +0.485 sec
  freq offset  : +2341056 (+35 ppm)
CLOCK_MONOTONIC_COARSE: ERROR: old_counter = 8090141164178, new_counter = 8090141164177
ERROR: old_counter = 8090141164177, new_counter = 8090141164165
errors: 2
  status       : 8193 sync
  time was     : 1720702929.000
  adjtime time : 1720702929.996
  time now     : 1720702929.000
  adjtime took : 4103 ns
  constant     : 7
  offset       : +0.167 sec
  freq offset  : +2610085 (+39 ppm)
CLOCK_MONOTONIC_RAW: OK
xargs: sh: exited with status 255; aborting

real    46m10.366s
user    56m43.443s
sys     26m32.073s

And like I expected it failed even without clock_adjtime (NTP), what I wasn't expecting is equal CPUs, hm (it was a bug in a code)

THREADS = 1
GLOBAL_CLOCK_COUNTER = 0
CLOCK_ITERATIONS = 1000000
NTP_THREAD = 0
SCHED_YIELD = 1
rdtsc: OK
CLOCK_MONOTONIC: OK
CLOCK_MONOTONIC_COARSE: ERROR: old_counter = 10532883087019, new_counter = 10532883087018(old CPU = 4, CPU = 4)
errors: 1
CLOCK_MONOTONIC_RAW: OK
xargs: sh: exited with status 255; aborting

real    22m7.468s
user    21m43.815s
sys     0m1.185s

UPD: even after fixing bug with getcpu, the CPU is still the same (race?):

THREADS = 1
GLOBAL_CLOCK_COUNTER = 0
CLOCK_ITERATIONS = 1000000
NTP_THREAD = 0
SCHED_YIELD = 1
rdtsc: OK
CLOCK_MONOTONIC: OK
CLOCK_MONOTONIC_COARSE: ERROR: old_counter = 10888448586573, new_counter = 10888448586563 (old CPU = 6, CPU = 6)
errors: 1
CLOCK_MONOTONIC_RAW: OK
xargs: sh: exited with status 255; aborting

real    1m43.967s
user    1m42.161s
sys     0m0.104s

Although I have chrony running, let's try without it

Without chrono running I cannot reproduce the issue (already for ~20 hours [1]), so it should be definitely clock adjustment in my case

[1]:

real    1069m27.351s
user    1050m48.394s
sys     0m56.961s

Seems that it has nothing to do with XEN, tried on GCP:

• n2-standard-64
• Linux b1 4.19.0-22-cloud-amd64 #1 SMP Debian 4.19.260-1 (2022-09-29) x86_64 GNU/Linux
• debian 10
• chronyd
• no chl 'select 1' in background

CLOCK_MONOTONIC_COARSE: ERROR: old_counter = 1232502913873, new_counter = 1232502913788 (old CPU = 7, CPU = 7)
errors: 1

Finally wrote a client with ADJ_FREQUENCY (and this is indeed what chronyd does) that reproduces the problem:

$ sudo unshare -T /tmp/test-clocks
status: 0000 sync, time was: 1720786185.000, adjtime time: 1720786185.000, time now: 1720786185.000, adjtime took: 5230 ns, constant: 7, offset: +0.004 sec, freq offset: -32768000 (-500 ppm)
status: 0000 sync, time was: 1720786185.000, adjtime time: 1720786185.000, time now: 1720786185.000, adjtime took: 2565 ns, constant: 7, offset: +0.004 sec, freq offset: -32768000 (-500 ppm)
ERROR: old_counter = 1273344844000358, new_counter = 1273344843999480, old CPU = 43, CPU = 43
status: 0001 sync, time was: 1720786185.000, adjtime time: 1720786185.000, time now: 1720786185.000, adjtime took: 2304 ns, constant: 7, offset: +0.004 sec, freq offset: -10345187 (-157 ppm)
status: 0001 sync, time was: 1720786185.000, adjtime time: 1720786185.000, time now: 1720786185.000, adjtime took: 2294 ns, constant: 7, offset: +0.004 sec, freq offset: -32768000 (-500 ppm)
status: 0001 sync, time was: 1720786185.000, adjtime time: 1720786185.000, time now: 1720786185.000, adjtime took: 2264 ns, constant: 7, offset: +0.004 sec, freq offset: -31677825 (-483 ppm)
ERROR: old_counter = 1273344844000324, new_counter = 1273344843999393, old CPU = 43, CPU = 43
status: 0001 sync, time was: 1720786185.000, adjtime time: 1720786185.000, time now: 1720786185.000, adjtime took: 2525 ns, constant: 7, offset: +0.004 sec, freq offset: -8361227 (-127 ppm)
status: 0000 sync, time was: 1720786185.000, adjtime time: 1720786185.000, time now: 1720786185.000, adjtime took: 2455 ns, constant: 7, offset: +0.004 sec, freq offset: -31666794 (-483 ppm)
status: 0000 sync, time was: 1720786185.000, adjtime time: 1720786185.000, time now: 1720786185.000, adjtime took: 2024 ns, constant: 7, offset: +0.004 sec, freq offset: -32768000 (-500 ppm)
status: 0001 sync, time was: 1720786185.000, adjtime time: 1720786185.000, time now: 1720786185.000, adjtime took: 3286 ns, constant: 7, offset: +0.004 sec, freq offset: -17611749 (-268 ppm)
CLOCK_MONOTONIC_COARSE: errors: 2
status: 0001 sync, time was: 1720786185.000, adjtime time: 1720786185.000, time now: 1720786185.000, adjtime took: 1743 ns, constant: 7, offset: +0.004 sec, freq offset: -32768000 (-500 ppm)

And this results from bare metal