Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

the time::WallClock::fastNowInSec() is getting more and more ahead #5833

Closed
UndefinedSy opened this issue Mar 11, 2024 · 4 comments
Closed
Labels
type/question Type: question about the product

Comments

@UndefinedSy
Copy link

Describe the bug (required)
the deviation of the time::WallClock::fastNowInSec() is unpredictable.

I've noticed that on my different machines, the timepoint generated by fastNowInSec is unpredictable.
some of the results show that the fastNowInSec is always consistent with the slowNowInSec, the others show that the differences between the two continue to widen.
I'm not sure if this will lead to a buggy behavior on the scenario that requires two timepoints to cal the duration. (like TTL or something)

Your Environments (required)

  • OS: uname -a

    Linux my-test-16 5.4.119-19-0009.11 Parser framework #1 SMP Wed Oct 5 18:41:07 CST 2022 x86_64 x86_64 x86_64 GNU/Linux

  • Compiler: g++ --version or clang++ --version

    g++ (GCC) 8.5.0 20210514 (Red Hat 8.5.0-4)

  • CPU: lscpu
Architecture:        x86_64
CPU op-mode(s):      32-bit, 64-bit
Byte Order:          Little Endian
CPU(s):              16
On-line CPU(s) list: 0-15
Thread(s) per core:  1
Core(s) per socket:  16
Socket(s):           1
NUMA node(s):        1
Vendor ID:           GenuineIntel
CPU family:          6
Model:               94
Model name:          Intel(R) Xeon(R) Gold 6133 CPU @ 2.50GHz
Stepping:            3
CPU MHz:             2499.998
BogoMIPS:            4999.99
Hypervisor vendor:   KVM
Virtualization type: full
L1d cache:           32K
L1i cache:           32K
L2 cache:            4096K
L3 cache:            28160K
NUMA node0 CPU(s):   0-15
Flags:               fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ss ht syscall nx pdpe1gb rdtscp lm constant_tsc rep_good nopl cpuid tsc_known_freq pni pclmulqdq ssse3 fma cx16 pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand hypervisor lahf_lm abm 3dnowprefetch invpcid_single pti fsgsbase bmi1 hle avx2 smep bmi2 erms invpcid rtm mpx rdseed adx smap clflushopt xsaveopt xsavec xgetbv1 arat
  • Commit id (e.g. a3ffc7d8)
  • latest

How To Reproduce(required)

Steps to reproduce the behavior:

#include <chrono>
#include <ctime>
#include <iostream>
#include <sstream>

#include "common/time/WallClock.h"

int main(int argc, char *argv[]) {
  // test std::chrono::system_clock
  auto std_system_now1 = std::chrono::system_clock::now();
  // test std::chrono::steady_clock
  auto std_steady_now1 = std::chrono::steady_clock::now();
  // test nebula::time::WallClock::slowNowInSec
  auto nebula_slow_now1 = nebula::time::WallClock::slowNowInSec();
  // test nebula::time::WallClock::fastNowInSec
  auto nebula_fast_now1 = nebula::time::WallClock::fastNowInSec();
  // output current date with format "YYYY-MM-DD HH:MM:SS"
  auto system_wallclock_datetime = std::chrono::system_clock::to_time_t(std_system_now1);
  std::stringstream ss;
  ss << std::put_time(std::localtime(&system_wallclock_datetime), "%Y-%m-%d %X");
  std::cout << "Current DataTime(system wallclock): "
            << ss.str() << std::endl;
  std::cout << "\tstd::chrono::system_clock::now(): "
            << std::chrono::duration_cast<std::chrono::seconds>(std_system_now1.time_since_epoch()).count() << std::endl;
  std::cout << "\tstd::chrono::steady_clock::now(): "
            << std::chrono::duration_cast<std::chrono::seconds>(std_steady_now1.time_since_epoch()).count() << std::endl;
  std::cout << "\tnebula::time::WallClock::slowNowInSec(): "
            << nebula_slow_now1 << std::endl;
  std::cout << "\tnebula::time::WallClock::fastNowInSec(): "
            << nebula_fast_now1 << std::endl;

  while (1) {
    // wait for 10s and re-genereate the time
    std::cout << "Wait for 10s..." << std::endl;
    std::this_thread::sleep_for(std::chrono::seconds(10));

    // test std::chrono::system_clock
    auto std_system_now2 = std::chrono::system_clock::now();
    // test std::chrono::steady_clock
    auto std_steady_now2 = std::chrono::steady_clock::now();
    // test nebula::time::WallClock::slowNowInSec
    auto nebula_slow_now2 = nebula::time::WallClock::slowNowInSec();
    // test nebula::time::WallClock::fastNowInSec
    auto nebula_fast_now2 = nebula::time::WallClock::fastNowInSec();
    // output current date with format "YYYY-MM-DD HH:MM:SS"
    system_wallclock_datetime = std::chrono::system_clock::to_time_t(std_system_now2);
    ss.str("");
    ss << std::put_time(std::localtime(&system_wallclock_datetime), "%Y-%m-%d %X");
    std::cout << "Current DataTime(system wallclock): "
              << ss.str() << std::endl;
    std::cout << "\tstd::chrono::system_clock::now(): "
              << std::chrono::duration_cast<std::chrono::seconds>(std_system_now2.time_since_epoch()).count() << std::endl;
    std::cout << "\tstd::chrono::steady_clock::now(): "
              << std::chrono::duration_cast<std::chrono::seconds>(std_steady_now2.time_since_epoch()).count() << std::endl;
    std::cout << "\tnebula::time::WallClock::slowNowInSec(): "
              << nebula_slow_now2 << std::endl;
    std::cout << "\tnebula::time::WallClock::fastNowInSec(): "
              << nebula_fast_now2 << std::endl;
    std::cout << "--------------------------------------------------------------\n";
  }
}

running the above code for a period of time, got the following result.

Current DataTime(system wallclock): 2024-03-11 11:35:12
        std::chrono::system_clock::now(): 1710128112
        std::chrono::steady_clock::now(): 4478530
        nebula::time::WallClock::slowNowInSec(): 1710128112
        nebula::time::WallClock::fastNowInSec(): 1710128216

Expected behavior
the fast one can be not so precise but the differences should be limited to a predictable range.

@UndefinedSy UndefinedSy added the type/bug Type: something is unexpected label Mar 11, 2024
@github-actions github-actions bot added affects/none PR/issue: this bug affects none version. severity/none Severity of bug labels Mar 11, 2024
@UndefinedSy
Copy link
Author

not sure if this is by-designed

@QingZ11 QingZ11 added type/question Type: question about the product and removed type/bug Type: something is unexpected severity/none Severity of bug affects/none PR/issue: this bug affects none version. labels Mar 11, 2024
@critical27
Copy link
Contributor

critical27 commented Mar 11, 2024

fast won't be accurate. IIRC, its difference is unpredictable. And yes, this may lead a problem when consider TTL if it use the fast function.

@dutor
Copy link
Contributor

dutor commented Mar 12, 2024

Years ago, I had noticed this buggy problem but didn't dive into it, and never have reproduced it ever since.

Yeah you are right. The so called fast version of WallClock is kind of not predictable because of how it works when converting the CPU ticks to realtime duration. It's subject to many aspects including the rdtsc instruction itself, accuracy of the system timer and even system load during caliberation.

So we discourage to use it in some critical situations.

If you are interesting in this issue, you could try out to utilize this kernel module to make the conversion mentioned above more accurate and eliminate the caliberation process.

@UndefinedSy
Copy link
Author

thx for the prompt reply.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
type/question Type: question about the product
Projects
None yet
Development

No branches or pull requests

4 participants