sin*_*raj 34 linux time profiling
章节旧问题包含初始问题(此后已添加进一步调查和结论).
跳到部分进一步调查下面的不同的定时的方法(详细比较rdtsc,clock_gettime和QueryThreadCycleTime).
我相信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_gettime与rdtsc对于相同的代码段(101个测量= 2525个读数25次运行):
clock_gettime:
其余的在900到5000 ns之间.
最小值:11 ns
rdtsc(注意:在此运行期间没有发生上下文切换,但如果发生这种情况,通常只会导致30000个刻度的单次测量):
1个1256蜱的测量值.
最低:274蜱
讨论:
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内核版本的计算机上测量了它:
CGT:
CPU:Core 2 Duo L9400 @ 1.86GHz
内核:Linux 2.6.40-4.fc15.i686#1 SMP Fri 7月29日18:54:39 UTC 2011 i686 i686 i386
结果:
clock_gettime开销:690-710 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之间达美时报:
直方图(左外范围的频率为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.c和rdtsc_overhead.c.
CPU:Core 2 Duo L9400 @ 1.86GHz
内核:Linux 2.6.40-4.fc15.i686#1 SMP Fri 7月29日18:54:39 UTC 2011 i686 i686 i386
结果:
达美时报:
直方图(左外范围的频率为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
结果:
达美时报:
直方图(左外范围的频率为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.c和qtct_overhead.c.
CPU:Core 2 6700 @ 2.66GHz
内核:Windows 7 64位
结果:
达美时报:
直方图(左外范围的频率为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时间不到一纳秒!此外,它还产生了一些非凡的大三角洲(超过300万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说:
的CLOCK_PROCESS_CPUTIME_ID和CLOCK_THREAD_CPUTIME_ID时钟实现上使用计时器从CPU的(TSC在i386,AR.ITC在Itanium)许多平台.这些寄存器在CPU之间可能不同,因此如果进程迁移到另一个CPU,这些时钟可能会返回虚假结果.
听起来这可能解释你的问题？也许您应该将进程锁定到一个CPU以获得稳定的结果？