linux - 为什么clock_gettime如此不稳定?

标签 linux time profiling

介绍

  • 部分“旧问题”包含初始问题(此后已添加了“进一步调查和结论”)。
  • 跳到下面的进一步研究部分,详细比较不同的计时方法(rdtscclock_gettimeQueryThreadCycleTime)。
  • 我相信CGT的不稳定行为可以归因于错误的内核或错误的CPU(请参见结论部分)。
  • 用于测试的代码位于该问题的底部(请参阅附录部分)。
  • 很抱歉的长度。


  • 旧问题

    简而言之:我正在使用clock_gettime来衡量许多代码段的执行时间。我在独立运行之间的测量结果非常不一致。与其他方法相比,该方法具有极高的标准偏差(请参阅下面的说明)。

    问题:与其他方法相比,clock_gettime是否给出如此不一致的测量值是有原因的吗?是否存在具有相同分辨率的替代方法来解决线程空闲时间?

    说明:我正在尝试分析C代码的一小部分。每个代码段的执行时间不超过几微秒。在一次运行中,每个代码段将执行数百次,从而产生runs × hundreds的测量值。

    我还必须只测量线程实际花费在执行上的时间(这就是rdtsc不适合的原因)。我还需要高分辨率(这就是times不适合的原因)。

    我尝试了以下方法:
  • rdtsc(在Linux和Windows上),
  • clock_gettime(在Linux上为“CLOCK_THREAD_CPUTIME_ID”;)和
  • QueryThreadCycleTime(在Windows上)。

  • 方法论:分析进行了25次运行。在每次运行中,单独的代码段重复101次。因此,我有2525个测量值。然后,我查看测量值的直方图,并计算一些基本信息(例如均值,std.dev。,中位数,众数,最小值和最大值)。

    我没有介绍如何测量这三种方法的“相似性”,但这只是涉及每个代码段中所用时间比例的基本比较(“比例”表示时间已标准化)。然后,我看看这些比例的纯粹差异。该比较表明,在25次运行中取平均值时,所有“rdtsc”,“QTCT”和“CGT”的比例均相同。但是,以下结果表明“CGT”具有非常大的标准偏差。这使得它在我的用例中无法使用。

    结果:

    相同代码段的clock_gettimerdtsc的比较(25次运行的101次测量= 2525个读数):
  • clock_gettime :
  • 1881年测量的11 ns,
  • 595的测量值(几乎正常分布)在3369到3414 ns之间,
  • 2次测量为11680 ns,
  • 1测量为1506022 ns,以及
  • 其余时间在900到5000 ns之间。
  • 分钟:11 ns
  • 最大值:1506022 ns
  • 平均值:1471.862 ns
  • 中位数:11 ns
  • 模式:11 ns
  • Stddev:29991.034
  • rdtsc (注意:在此运行期间未发生上下文切换,但是如果发生此切换,通常只会进行30000个滴答左右的单次测量):
  • 在274和325滴答之间进行1178次测量
  • 306的测量值介于326和375之间
  • 在376和425滴答之间进行910次测量
  • 在426和990滴答之间进行129次测量,
  • 1测量1240个滴答,
  • 1个测量的1256个刻度。
  • 敏:274个滴答声
  • 最大值:1256个滴答声
  • 均值:355.806滴答声
  • 中位数:333 ticks
  • 模式:376个滴答声
  • 标准差:83.896

  • 讨论:
  • rdtsc在Linux和Windows上均提供非常相似的结果。它具有可接受的标准偏差-实际上相当一致/稳定。但是,它不考虑线程空闲时间。因此,上下文切换使测量变得不稳定(在Windows上我经常观察到这一点:平均大约1000个滴答声的代码段有时会不时地消耗〜30000个滴答声-肯定是由于抢占而来)。
  • QueryThreadCycleTime给出非常一致的测量值-即与rdtsc相比,标准偏差要低得多。当没有上下文切换发生时,此方法几乎与rdtsc相同。
  • 另一方面,
  • clock_gettime产生极其不一致的结果(不仅在运行之间,而且在测量之间)。标准偏差非常大(与rdtsc相比)。

  • 我希望统计数字可以。但是,两种方法之间的测量值出现如此差异的原因可能是什么?当然,有缓存,CPU/内核迁移等。但是,这一切都不应对“rdtsc”和“clock_gettime”之间的任何此类差异负责。到底是怎么回事?

    进一步的调查

    我对此进行了进一步调查。我做了两件事:
  • 测量仅调用clock_gettime(CLOCK_THREAD_CPUTIME_ID, &t)(请参阅附录中的代码1)和
  • 的开销
    在称为clock_gettime的简单循环中将
  • 并将读数存储到数组中(请参阅附录中的代码2)。我测量了增量时间(相继的测量时间中的差异,应该与clock_gettime调用的开销相对应)。

  • 我已经在具有两个不同Linux Kernel版本的两台不同计算机上对其进行了测量:

    CGT :
  • CPU :Core 2 Duo L9400 @ 1.86GHz

    内核:Linux 2.6.40-4.fc15.i686#1 SMP Fri Jul 29 18:54:39 UTC 2011 i686 i686 i386

    结果:
  • 估计的clock_gettime开销:690-710 ns之间
  • Delta时间:
  • 平均:815.22 ns
  • 中位数:713 ns
  • 模式:709 ns
  • 分钟:698 ns
  • 最大值:23359 ns
  • 直方图(遗漏范围的频率为0):
          Range       |  Frequency
    ------------------+-----------
      697 < x ≤ 800   ->     78111  <-- cached?
      800 < x ≤ 1000  ->     16412
     1000 < x ≤ 1500  ->         3
     1500 < x ≤ 2000  ->      4836  <-- uncached?
     2000 < x ≤ 3000  ->       305
     3000 < x ≤ 5000  ->       161
     5000 < x ≤ 10000 ->       105
    10000 < x ≤ 15000 ->        53
    15000 < x ≤ 20000 ->         8
    20000 < x         ->         5
    
  • CPU :4×双核AMD Opteron处理器275

    内核:Linux 2.6.26-2-amd64#1 SMP Sun Jun 20 20:16:30 UTC 2010 x86_64 GNU/Linux

    结果:
  • 估计的clock_gettime开销:279-283 ns之间
  • Delta时间:
  • 平均:320.00
  • 中位数:1
  • 模式:1
  • 最小值:1
  • 最大值:3495529
  • 直方图(遗漏范围的频率为0):
          Range         |  Frequency
    --------------------+-----------
              x ≤ 1     ->     86738  <-- cached?
        282 < x ≤ 300   ->     13118  <-- uncached?
        300 < x ≤ 440   ->        78
       2000 < x ≤ 5000  ->        52
       5000 < x ≤ 30000 ->         5
    3000000 < x         ->         8
    

  • RDTSC :

    相关代码rdtsc_delta.crdtsc_overhead.c
  • CPU :Core 2 Duo L9400 @ 1.86GHz

    内核:Linux 2.6.40-4.fc15.i686#1 SMP Fri Jul 29 18:54:39 UTC 2011 i686 i686 i386

    结果:
  • 估计的开销:39-42滴答之间
  • Delta时间:
  • 平均:52.46滴答声
  • 中位数:42个滴答声
  • 模式:42个滴答声
  • 最低:35 ticks
  • 最多:28700个滴答声
  • 直方图(遗漏范围的频率为0):
          Range       |  Frequency
    ------------------+-----------
       34 < x ≤ 35    ->     16240  <-- cached?
       41 < x ≤ 42    ->     63585  <-- uncached? (small difference)
       48 < x ≤ 49    ->     19779  <-- uncached?
       49 < x ≤ 120   ->       195
     3125 < x ≤ 5000  ->       144
     5000 < x ≤ 10000 ->        45
    10000 < x ≤ 20000 ->         9
    20000 < x         ->         2
    
  • CPU :4×双核AMD Opteron处理器275

    内核:Linux 2.6.26-2-amd64#1 SMP Sun Jun 20 20:16:30 UTC 2010 x86_64 GNU/Linux

    结果:
  • 估计的开销:在13.7-17.0滴答之间
  • Delta时间:
  • 平均:35.44滴答声
  • 中位数:16个滴答声
  • 模式:16个滴答声
  • 最少:14个滴答声
  • 最多:16372个滴答声
  • 直方图(遗漏范围的频率为0):
          Range       |  Frequency
    ------------------+-----------
       13 < x ≤ 14    ->       192
       14 < x ≤ 21    ->     78172  <-- cached?
       21 < x ≤ 50    ->     10818
       50 < x ≤ 103   ->     10624  <-- uncached?
     5825 < x ≤ 6500  ->        88
     6500 < x ≤ 8000  ->        88
     8000 < x ≤ 10000 ->        11
    10000 < x ≤ 15000 ->         4
    15000 < x ≤ 16372 ->         2
    

  • QTCT :

    相关代码qtct_delta.cqtct_overhead.c
  • CPU :核心2 6700 @ 2.66GHz

    内核:Windows 7 64位

    结果:
  • 估计的开销:890-940滴答之间
  • Delta时间:
  • 平均:1057.30滴答声
  • 中位数:890 ticks
  • 模式:890个滴答声
  • 分钟:880个滴答声
  • 最多:29400个滴答声
  • 直方图(遗漏范围的频率为0):
          Range       |  Frequency
    ------------------+-----------
      879 < x ≤ 890   ->     71347  <-- cached?
      895 < x ≤ 1469  ->       844
     1469 < x ≤ 1600  ->     27613  <-- uncached?
     1600 < x ≤ 2000  ->        55
     2000 < x ≤ 4000  ->        86
     4000 < x ≤ 8000  ->        43
     8000 < x ≤ 16000 ->        10
    16000 < x         ->         1
    


  • 结论

    我相信,我的问题的答案将是在我的计算机上执行错误的实现(该计算机使用具有旧Linux内核的AMD CPU)。

    使用旧内核的AMD机器的CGT结果显示了一些极端的读数。如果我们查看增量时间,就会发现最频繁的增量是1 ns。这意味着对clock_gettime的调用花费了不到一纳秒的时间!而且,它还产生了许多非常大的增量(超过3000000 ns)!这似乎是错误的行为。 (也许无法解释的核心迁移?)

    备注:
  • CGT和QTCT的开销很大。
  • 也很难考虑它们的开销,因为CPU缓存似乎有很大的不同。
  • 也许坚持RDTSC,将进程锁定在一个内核上,并分配实时优先级,这是最准确的方式来告诉您一段代码使用了多少个周期...


  • 附录

    代码1 :clock_gettime_overhead.c
    #include <time.h>
    #include <stdio.h>
    #include <stdint.h>
    
    /* Compiled & executed with:
    
        gcc clock_gettime_overhead.c -O0 -lrt -o clock_gettime_overhead
        ./clock_gettime_overhead 100000
    */
    
    int main(int argc, char **args) {
        struct timespec tstart, tend, dummy;
        int n, N;
        N = atoi(args[1]);
        clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tstart);
        for (n = 0; n < N; ++n) {
            clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
            clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
            clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
            clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
            clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
            clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
            clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
            clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
            clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
            clock_gettime(CLOCK_THREAD_CPUTIME_ID, &dummy);
        }
        clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tend);
        printf("Estimated overhead: %lld ns\n",
                ((int64_t) tend.tv_sec * 1000000000 + (int64_t) tend.tv_nsec
                        - ((int64_t) tstart.tv_sec * 1000000000
                                + (int64_t) tstart.tv_nsec)) / N / 10);
        return 0;
    }
    

    代码2 :clock_gettime_delta.c
    #include <time.h>
    #include <stdio.h>
    #include <stdint.h>
    
    /* Compiled & executed with:
    
        gcc clock_gettime_delta.c -O0 -lrt -o clock_gettime_delta
        ./clock_gettime_delta > results
    */
    
    #define N 100000
    
    int main(int argc, char **args) {
        struct timespec sample, results[N];
        int n;
        for (n = 0; n < N; ++n) {
            clock_gettime(CLOCK_THREAD_CPUTIME_ID, &sample);
            results[n] = sample;
        }
        printf("%s\t%s\n", "Absolute time", "Delta");
        for (n = 1; n < N; ++n) {
            printf("%lld\t%lld\n",
                   (int64_t) results[n].tv_sec * 1000000000 + 
                       (int64_t)results[n].tv_nsec,
                   (int64_t) results[n].tv_sec * 1000000000 + 
                       (int64_t) results[n].tv_nsec - 
                       ((int64_t) results[n-1].tv_sec * 1000000000 + 
                            (int64_t)results[n-1].tv_nsec));
        }
        return 0;
    }
    

    代码3 :rdtsc.h
    static uint64_t rdtsc() {
    #if defined(__GNUC__)
    #   if defined(__i386__)
        uint64_t x;
        __asm__ volatile (".byte 0x0f, 0x31" : "=A" (x));
        return x;
    #   elif defined(__x86_64__)
        uint32_t hi, lo;
        __asm__ __volatile__ ("rdtsc" : "=a"(lo), "=d"(hi));
        return ((uint64_t)lo) | ((uint64_t)hi << 32);
    #   else
    #       error Unsupported architecture.
    #   endif
    #elif defined(_MSC_VER)
        return __rdtsc();
    #else
    #   error Other compilers not supported...
    #endif
    }
    

    代码4 :rdtsc_delta.c
    #include <stdio.h>
    #include <stdint.h>
    #include "rdtsc.h"
    
    /* Compiled & executed with:
    
        gcc rdtsc_delta.c -O0 -o rdtsc_delta
        ./rdtsc_delta > rdtsc_delta_results
    
    Windows:
    
        cl -Od rdtsc_delta.c
        rdtsc_delta.exe > windows_rdtsc_delta_results
    */
    
    #define N 100000
    
    int main(int argc, char **args) {
        uint64_t results[N];
        int n;
        for (n = 0; n < N; ++n) {
            results[n] = rdtsc();
        }
        printf("%s\t%s\n", "Absolute time", "Delta");
        for (n = 1; n < N; ++n) {
            printf("%lld\t%lld\n", results[n], results[n] - results[n-1]);
        }
        return 0;
    }
    

    代码5 :rdtsc_overhead.c
    #include <time.h>
    #include <stdio.h>
    #include <stdint.h>
    #include "rdtsc.h"
    
    /* Compiled & executed with:
    
        gcc rdtsc_overhead.c -O0 -lrt -o rdtsc_overhead
        ./rdtsc_overhead 1000000 > rdtsc_overhead_results
    
    Windows:
    
        cl -Od rdtsc_overhead.c
        rdtsc_overhead.exe 1000000 > windows_rdtsc_overhead_results
    */
    
    int main(int argc, char **args) {
        uint64_t tstart, tend, dummy;
        int n, N;
        N = atoi(args[1]);
        tstart = rdtsc();
        for (n = 0; n < N; ++n) {
            dummy = rdtsc();
            dummy = rdtsc();
            dummy = rdtsc();
            dummy = rdtsc();
            dummy = rdtsc();
            dummy = rdtsc();
            dummy = rdtsc();
            dummy = rdtsc();
            dummy = rdtsc();
            dummy = rdtsc();
        }
        tend = rdtsc();
        printf("%G\n", (double)(tend - tstart)/N/10);
        return 0;
    }
    

    代码6 :qtct_delta.c
    #include <stdio.h>
    #include <stdint.h>
    #include <Windows.h>
    
    /* Compiled & executed with:
    
        cl -Od qtct_delta.c
        qtct_delta.exe > windows_qtct_delta_results
    */
    
    #define N 100000
    
    int main(int argc, char **args) {
        uint64_t ticks, results[N];
        int n;
        for (n = 0; n < N; ++n) {
            QueryThreadCycleTime(GetCurrentThread(), &ticks);
            results[n] = ticks;
        }
        printf("%s\t%s\n", "Absolute time", "Delta");
        for (n = 1; n < N; ++n) {
            printf("%lld\t%lld\n", results[n], results[n] - results[n-1]);
        }
        return 0;
    }
    

    代码7 :qtct_overhead.c
    #include <stdio.h>
    #include <stdint.h>
    #include <Windows.h>
    
    /* Compiled & executed with:
    
        cl -Od qtct_overhead.c
        qtct_overhead.exe 1000000
    */
    
    int main(int argc, char **args) {
        uint64_t tstart, tend, ticks;
        int n, N;
        N = atoi(args[1]);
        QueryThreadCycleTime(GetCurrentThread(), &tstart);
        for (n = 0; n < N; ++n) {
            QueryThreadCycleTime(GetCurrentThread(), &ticks);
            QueryThreadCycleTime(GetCurrentThread(), &ticks);
            QueryThreadCycleTime(GetCurrentThread(), &ticks);
            QueryThreadCycleTime(GetCurrentThread(), &ticks);
            QueryThreadCycleTime(GetCurrentThread(), &ticks);
            QueryThreadCycleTime(GetCurrentThread(), &ticks);
            QueryThreadCycleTime(GetCurrentThread(), &ticks);
            QueryThreadCycleTime(GetCurrentThread(), &ticks);
            QueryThreadCycleTime(GetCurrentThread(), &ticks);
            QueryThreadCycleTime(GetCurrentThread(), &ticks);
        }
        QueryThreadCycleTime(GetCurrentThread(), &tend);
        printf("%G\n", (double)(tend - tstart)/N/10);
        return 0;
    }
    

    最佳答案

    由于CLOCK_THREAD_CPUTIME_ID是使用rdtsc实现的,因此很可能会遇到与它相同的问题。 clock_gettime的手册页显示:

    The CLOCK_PROCESS_CPUTIME_ID and CLOCK_THREAD_CPUTIME_ID clocks are realized on many platforms using timers from the CPUs (TSC on i386, AR.ITC on Itanium). These registers may differ between CPUs and as a consequence these clocks may return bogus results if a process is migrated to another CPU.



    听起来好像可以解释您的问题?也许您应该将进程锁定到一个CPU以获得稳定的结果?

    关于linux - 为什么clock_gettime如此不稳定?,我们在Stack Overflow上找到一个类似的问题: https://stackoverflow.com/questions/6814792/

    相关文章:

    linux - Bash 脚本中 FTP 将文件复制到远程计算机失败

    java - java打印日期和时间

    java - Java 中的日期时间 - 如何找到从某个日期到 1970 年的毫秒数?

    linux - 如何使用文件路径自动完成 bash 命令行?

    Linux:按名称顺序批量重命名多个文件到父目录+后缀

    php - 如何使用两个时间戳之间的时间表计算时间差?

    java - NoClassDefFound错误: bea/jmapi/MethodProfileData when profiling app using JRockit Mission Control

    windows - 我可以使用哪些工具来确定我的应用程序的硬件要求?

    java - jvisualvm:卡在 “Loading Heap Dump...” 屏幕上

    python - 了解 python subprocess.check_output 的第一个参数和 shell=True