为什么 clock_gettime(CLOCK_REALTIME, ..) 上的调用延迟差异如此之大？
Why does the call latency on clock_gettime(CLOCK_REALTIME, ..) vary so much?
我正在计算 clock_gettime(CLOCK_REALTIME,...) 通话的时间。 "Back in the day" 我过去常常在循环的顶部调用它一次，因为这是一个相当昂贵的调用。但现在，我希望通过 vDSO 和一些时钟改进，它可能不会那么慢。
我写了一些测试代码，使用 __rdtscp 来计时对 clock_gettime 的重复调用（rdtscp 调用绕过一个调用 clock_gettime 的循环并添加了结果放在一起，这样编译器就不会优化太多）。
如果我快速连续调用 clock_gettime()，时间长度会从大约 45k 个时钟周期减少到 500 个周期。我认为其中一些可能导致第一次调用必须加载 vDSO 代码（对我来说仍然没有完全意义），但是如何需要几次调用才能获得 500 我根本无法解释，而且这种行为似乎无论我如何测试它都保持不变：
42467
1114
1077
496
455
但是，如果我在对 clock_gettime 的调用之间休眠（一秒或十秒，无关紧要），它只会达到大约 4.7k 个周期的稳定状态：
这里睡了 10 秒：
28293
1093
4729
4756
4736
此处 1 秒睡眠：
61578
855
4753
4741
5645
4753
4732
缓存行为似乎无法描述这一点（在桌面系统上什么都不做）。我应该为 clock_gettime 的通话预算多少？为什么调用会越来越快？为什么睡少量时间如此重要？
tl;dr 我试图了解调用所需的时间 clock_gettime(CLOCK_REALTIME,...) 不明白为什么快速连续调用时它运行得更快通话间隔一秒。
更新：这是 proc 0
上的 cpuinfo
processor : 0
vendor_id : GenuineIntel
cpu family : 6
model : 158
model name : Intel(R) Core(TM) i7-7700HQ CPU @ 2.80GHz
stepping : 9
microcode : 0x84
cpu MHz : 2800.000
cache size : 6144 KB
physical id : 0
siblings : 8
core id : 0
cpu cores : 4
apicid : 0
initial apicid : 0
fpu : yes
fpu_exception : yes
cpuid level : 22
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc art arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid aperfmperf tsc_known_freq pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm 3dnowprefetch cpuid_fault epb intel_pt tpr_shadow vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid mpx rdseed adx smap clflushopt xsaveopt xsavec xgetbv1 xsaves dtherm ida arat pln pts hwp hwp_notify hwp_act_window hwp_epp
bugs :
bogomips : 5616.00
clflush size : 64
cache_alignment : 64
address sizes : 39 bits physical, 48 bits virtual
power management:
这是重新创建的测试代码：
#include <time.h>
#include <unistd.h>
#include <stdio.h>
#include <stdlib.h>
#include <x86intrin.h>
// compiled gcc -Wall -O3 -o clockt clockt.cpp
// called glockt sleeptime trials loops
unsigned long long now() {
struct timespec s;
clock_gettime(CLOCK_REALTIME, &s);
return (s.tv_sec * 1000000000ull) + s.tv_nsec;
}
int main(int argc, char **argv) {
int sleeptime = atoi(argv[1]);
int trials = atoi(argv[2]);
int loops = atoi(argv[3]);
unsigned long long x, y, n = 0;
unsigned int d;
x = __rdtscp(&d);
n = now();
asm volatile("": "+r" (n));
y = __rdtscp(&d);
printf("init run %lld\n", (y-x));
for(int t = 0; t < trials; ++t) {
if(sleeptime > 0) sleep(sleeptime);
x = __rdtscp(&d);
for(int l = 0; l < loops; ++l) {
n = now();
asm volatile("": "+r" (n));
}
y = __rdtscp(&d);
printf("trial %d took %lld\n", t, (y-x));
}
exit(0);
}
第一次调用 clock_gettime 时，包含该函数指令的页面出现页面错误。在我的系统上，这是一个软页面错误，需要几千个周期来处理（最多 10,000 个周期）。我的 CPU 是 运行ning，频率为 3.4GHz。我认为您的 CPU 是 运行ning 的频率要低得多，因此处理系统上的页面错误将花费更多时间。但这里的要点是，第一次调用 clock_gettime 将比以后的调用花费更多的时间，这就是您所观察到的。
您的代码表现出的第二个主要影响是指令高速缓存未命中导致的严重停顿。看起来您只调用了两个函数，即 now 和 printf，但这些函数调用其他函数并且它们都在 L1 指令缓存上竞争。总体而言，这取决于所有这些函数在物理地址 space 中的对齐方式。当休眠时间为零秒时，由于指令高速缓存未命中导致的停顿时间实际上相对较小（您可以使用 ICACHE.IFETCH_STALL 性能计数器来测量）。然而，当睡眠时间大于零秒时，这个停顿时间会变得明显更长，因为 OS 将在同一核心上调度一些其他线程到 运行，并且该线程将使用不同的指令和数据。这解释了为什么当你睡觉时，clock_gettime 需要更多的时间来执行。
现在关于第二次和以后的测量。来自问题：
42467
1114
1077
496
455
我在我的系统上观察到，第二次测量不一定比后来的测量大。我相信这在您的系统上也是如此。事实上，你睡10秒或1秒似乎就是这样。在外层循环中，now和printf这两个函数包含了数千条动态指令，它们也访问了L1数据缓存。您在第二次和以后的测量之间看到的可变性是可重现的。所以它是函数本身固有的。请注意，rdtscp 指令本身的执行时间可能会相差 4 个周期。另见 this.
实际上，当所需精度最多为一百万个周期时，clock_gettime 很有用。否则，可能会产生误导。
我无法重现您的结果。即使有很长的睡眠时间（10 秒）和少量循环（100），我总是得到少于 100 个时钟的计时（在我的 2.6 GHz 系统上少于 38 ns）。
例如：
./clockt 10 10 100
init run 14896
trial 0 took 8870 (88 cycles per call)
trial 1 took 8316 (83 cycles per call)
trial 2 took 8384 (83 cycles per call)
trial 3 took 8796 (87 cycles per call)
trial 4 took 9424 (94 cycles per call)
trial 5 took 9054 (90 cycles per call)
trial 6 took 8394 (83 cycles per call)
trial 7 took 8346 (83 cycles per call)
trial 8 took 8868 (88 cycles per call)
trial 9 took 8930 (89 cycles per call)
除了测量或用户错误（通常是最可能的原因）之外，最可能的解释是您的系统没有使用 rdtsc 作为时间源，因此进行了系统调用。您可以自己明确地配置时钟源，或者使用一些启发式算法，只有在当前系统看起来合适时才会基于 select rdtsc clock_gettime。
第二个最可能的原因是 clock_gettime(CLOCK_REALTIME) 没有通过您系统上的 VDSO，即使 rdtsc 最终被使用也是系统调用。我想这可能是由于旧的 libc 版本或类似的原因。
第三个最可能的原因是 rdtsc 在您的系统上运行缓慢，可能是因为它在您的系统上被虚拟化或禁用，并通过 VM 退出或 OS 陷阱实施。
单循环结果
尝试每个循环调用一次 clock_gettime，在前几次试验后我仍然得到 "fast" 结果。例如，./clockt 0 20 1 给出：
init run 15932
trial 0 took 352 (352 cycles per call)
trial 1 took 196 (196 cycles per call)
trial 2 took 104 (104 cycles per call)
trial 3 took 104 (104 cycles per call)
trial 4 took 104 (104 cycles per call)
trial 5 took 104 (104 cycles per call)
trial 6 took 102 (102 cycles per call)
trial 7 took 104 (104 cycles per call)
...
请注意，我对测试程序做了一个修改，以打印每次调用的时间，这似乎比总时间更有用。 printf 行修改为：
printf("trial %d took %lld (%lld cycles per call)\n", t, (y-x), (y-x)/loops);
我正在计算 clock_gettime(CLOCK_REALTIME,...) 通话的时间。 "Back in the day" 我过去常常在循环的顶部调用它一次，因为这是一个相当昂贵的调用。但现在，我希望通过 vDSO 和一些时钟改进，它可能不会那么慢。
我写了一些测试代码，使用 __rdtscp 来计时对 clock_gettime 的重复调用（rdtscp 调用绕过一个调用 clock_gettime 的循环并添加了结果放在一起，这样编译器就不会优化太多）。
如果我快速连续调用 clock_gettime()，时间长度会从大约 45k 个时钟周期减少到 500 个周期。我认为其中一些可能导致第一次调用必须加载 vDSO 代码（对我来说仍然没有完全意义），但是如何需要几次调用才能获得 500 我根本无法解释，而且这种行为似乎无论我如何测试它都保持不变：
42467
1114
1077
496
455
但是，如果我在对 clock_gettime 的调用之间休眠（一秒或十秒，无关紧要），它只会达到大约 4.7k 个周期的稳定状态：
这里睡了 10 秒：
28293
1093
4729
4756
4736
此处 1 秒睡眠：
61578
855
4753
4741
5645
4753
4732
缓存行为似乎无法描述这一点（在桌面系统上什么都不做）。我应该为 clock_gettime 的通话预算多少？为什么调用会越来越快？为什么睡少量时间如此重要？
tl;dr 我试图了解调用所需的时间 clock_gettime(CLOCK_REALTIME,...) 不明白为什么快速连续调用时它运行得更快通话间隔一秒。
更新：这是 proc 0
上的 cpuinfoprocessor : 0
vendor_id : GenuineIntel
cpu family : 6
model : 158
model name : Intel(R) Core(TM) i7-7700HQ CPU @ 2.80GHz
stepping : 9
microcode : 0x84
cpu MHz : 2800.000
cache size : 6144 KB
physical id : 0
siblings : 8
core id : 0
cpu cores : 4
apicid : 0
initial apicid : 0
fpu : yes
fpu_exception : yes
cpuid level : 22
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc art arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid aperfmperf tsc_known_freq pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm 3dnowprefetch cpuid_fault epb intel_pt tpr_shadow vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid mpx rdseed adx smap clflushopt xsaveopt xsavec xgetbv1 xsaves dtherm ida arat pln pts hwp hwp_notify hwp_act_window hwp_epp
bugs :
bogomips : 5616.00
clflush size : 64
cache_alignment : 64
address sizes : 39 bits physical, 48 bits virtual
power management:
这是重新创建的测试代码：
#include <time.h>
#include <unistd.h>
#include <stdio.h>
#include <stdlib.h>
#include <x86intrin.h>
// compiled gcc -Wall -O3 -o clockt clockt.cpp
// called glockt sleeptime trials loops
unsigned long long now() {
struct timespec s;
clock_gettime(CLOCK_REALTIME, &s);
return (s.tv_sec * 1000000000ull) + s.tv_nsec;
}
int main(int argc, char **argv) {
int sleeptime = atoi(argv[1]);
int trials = atoi(argv[2]);
int loops = atoi(argv[3]);
unsigned long long x, y, n = 0;
unsigned int d;
x = __rdtscp(&d);
n = now();
asm volatile("": "+r" (n));
y = __rdtscp(&d);
printf("init run %lld\n", (y-x));
for(int t = 0; t < trials; ++t) {
if(sleeptime > 0) sleep(sleeptime);
x = __rdtscp(&d);
for(int l = 0; l < loops; ++l) {
n = now();
asm volatile("": "+r" (n));
}
y = __rdtscp(&d);
printf("trial %d took %lld\n", t, (y-x));
}
exit(0);
}
第一次调用 clock_gettime 时，包含该函数指令的页面出现页面错误。在我的系统上，这是一个软页面错误，需要几千个周期来处理（最多 10,000 个周期）。我的 CPU 是 运行ning，频率为 3.4GHz。我认为您的 CPU 是 运行ning 的频率要低得多，因此处理系统上的页面错误将花费更多时间。但这里的要点是，第一次调用 clock_gettime 将比以后的调用花费更多的时间，这就是您所观察到的。
您的代码表现出的第二个主要影响是指令高速缓存未命中导致的严重停顿。看起来您只调用了两个函数，即 now 和 printf，但这些函数调用其他函数并且它们都在 L1 指令缓存上竞争。总体而言，这取决于所有这些函数在物理地址 space 中的对齐方式。当休眠时间为零秒时，由于指令高速缓存未命中导致的停顿时间实际上相对较小（您可以使用 ICACHE.IFETCH_STALL 性能计数器来测量）。然而，当睡眠时间大于零秒时，这个停顿时间会变得明显更长，因为 OS 将在同一核心上调度一些其他线程到 运行，并且该线程将使用不同的指令和数据。这解释了为什么当你睡觉时，clock_gettime 需要更多的时间来执行。
现在关于第二次和以后的测量。来自问题：
42467
1114
1077
496
455
我在我的系统上观察到，第二次测量不一定比后来的测量大。我相信这在您的系统上也是如此。事实上，你睡10秒或1秒似乎就是这样。在外层循环中，now和printf这两个函数包含了数千条动态指令，它们也访问了L1数据缓存。您在第二次和以后的测量之间看到的可变性是可重现的。所以它是函数本身固有的。请注意，rdtscp 指令本身的执行时间可能会相差 4 个周期。另见 this.
实际上，当所需精度最多为一百万个周期时，clock_gettime 很有用。否则，可能会产生误导。
我无法重现您的结果。即使有很长的睡眠时间（10 秒）和少量循环（100），我总是得到少于 100 个时钟的计时（在我的 2.6 GHz 系统上少于 38 ns）。
例如：
./clockt 10 10 100
init run 14896
trial 0 took 8870 (88 cycles per call)
trial 1 took 8316 (83 cycles per call)
trial 2 took 8384 (83 cycles per call)
trial 3 took 8796 (87 cycles per call)
trial 4 took 9424 (94 cycles per call)
trial 5 took 9054 (90 cycles per call)
trial 6 took 8394 (83 cycles per call)
trial 7 took 8346 (83 cycles per call)
trial 8 took 8868 (88 cycles per call)
trial 9 took 8930 (89 cycles per call)
除了测量或用户错误（通常是最可能的原因）之外，最可能的解释是您的系统没有使用 rdtsc 作为时间源，因此进行了系统调用。您可以自己明确地配置时钟源，或者使用一些启发式算法，只有在当前系统看起来合适时才会基于 select rdtsc clock_gettime。
第二个最可能的原因是 clock_gettime(CLOCK_REALTIME) 没有通过您系统上的 VDSO，即使 rdtsc 最终被使用也是系统调用。我想这可能是由于旧的 libc 版本或类似的原因。
第三个最可能的原因是 rdtsc 在您的系统上运行缓慢，可能是因为它在您的系统上被虚拟化或禁用，并通过 VM 退出或 OS 陷阱实施。
单循环结果
尝试每个循环调用一次 clock_gettime，在前几次试验后我仍然得到 "fast" 结果。例如，./clockt 0 20 1 给出：
init run 15932
trial 0 took 352 (352 cycles per call)
trial 1 took 196 (196 cycles per call)
trial 2 took 104 (104 cycles per call)
trial 3 took 104 (104 cycles per call)
trial 4 took 104 (104 cycles per call)
trial 5 took 104 (104 cycles per call)
trial 6 took 102 (102 cycles per call)
trial 7 took 104 (104 cycles per call)
...
请注意，我对测试程序做了一个修改，以打印每次调用的时间，这似乎比总时间更有用。 printf 行修改为：
printf("trial %d took %lld (%lld cycles per call)\n", t, (y-x), (y-x)/loops);