Yanyg - SAN Software Engineer

程序执行时间与代码执行时间评估/Benchmark process execution time and code execution time

目录

1 评估进程执行时间

Shell环境下使用time评估。bash shell有内置的time,系统提供功能更多的time命令 (GNU TimeGNU Time Git,安装位置一般是/usr/bin/time)。GNU Time基于 \(gettimeofday\)和\(wait3\)实现。

~$ time sudo dd if=/dev/sdb of=/dev/null bs=4K count=1K iflag=direct
1024+0 records in
1024+0 records out
4194304 bytes (4.2 MB) copied, 0.370473 s, 11.3 MB/s

real    0m0.380s
user    0m0.004s
sys     0m0.004s
~$ /usr/bin/time --format "Time:\n\t%E real,\n\t%U user,\n\t%S sys" sudo dd if=/dev/sdb of=/dev/null bs=4K count=1K iflag=direct
1024+0 records in
1024+0 records out
4194304 bytes (4.2 MB) copied, 0.39669 s, 10.6 MB/s

Time:
        0:00.40 real,
        0.00 user,
        0.01 sys

2 代码段执行时间评估

2.1 Methods

使用\(time\)、\(gettimeofday\)、\(clock\_gettime\)获取秒、微秒、纳秒级别的时间精度,但上述三者都触发系统调用或vdso。使用内嵌汇编和CPU指令RDTSC获取更高精度(与 CPU主频相同)的时间精度。

2.2 Test Results

通过测试代码,在我的T430(CPU 2.89Hz Cores 4)上2594 TSC为1微秒(10-6),2.8 TSC 为1纳秒(这和CPU的频率2.8GHz是一致的)。系统调用成本大概240-310 TSC,而vdso(虚拟系统调用)110-130 TSC。vdso是系统调用成本的40%左右。传递编译参数\(-static\)使用系统调用,不传递该参数默认为动态链接,在支持vdso系统上优先使用vdso。

~$ lscpu
Architecture:          x86_64
CPU op-mode(s):        32-bit, 64-bit
Byte Order:            Little Endian
CPU(s):                4
On-line CPU(s) list:   0-3
Thread(s) per core:    2
Core(s) per socket:    2
Socket(s):             1
NUMA node(s):          1
Vendor ID:             GenuineIntel
CPU family:            6
Model:                 60
Model name:            Intel(R) Core(TM) i7-4600M CPU @ 2.90GHz
Stepping:              3
CPU MHz:               2904.248
CPU max MHz:           3600.0000
CPU min MHz:           800.0000
BogoMIPS:              5786.24
Virtualization:        VT-x
L1d cache:             32K
L1i cache:             32K
L2 cache:              256K
L3 cache:              4096K
NUMA node0 CPU(s):     0-3
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 arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc aperfmperf eagerfpu pni pclmulqdq dtes64 monitor ds_cpl vmx smx 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 epb tpr_shadow vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 hle avx2 smep bmi2 erms invpcid rtm xsaveopt dtherm ida arat pln pts
~$ gcc -Wall -O3 benchmark-time.c -o test-benchmark -static  #<-- remove -static for vdso test
~$ taskset 0x1 ./test-benchmark
init TSC to microsecond (about 2 seconds)
        1000 system call tsc = 296148
        tsc2microsec=2893 tsc2clock=2 system_call=296 [tsc=5787006236, millisecond=2000127, nanosec=2000123893, tsc2nanosec=2.893324]
rdtsc test limits = 100000000
        elpased(544894707) [start=8746910496255, end=8747455390962, time=0.188349]
rdtsc test limits = 1000000
        elpased(5561326) [start=8747455521373, end=8747461082699, time=0.001922]
rdtsc test limits = 10000
        elpased(92467) [start=8747461122832, end=8747461215299, time=0.000031]
rdtsc test limits = 1000
        elpased(5018) [start=8747461231815, end=8747461236833, time=0.000001]
rdtsc test limits = 100
        elpased(539) [start=8747461246770, end=8747461247309, time=0.000000]
gettimeofday test limits = 100000000
        elpased(181964) [time=0.181964]
gettimeofday test limits = 1000000
        elpased(1737) [time=0.001737]
gettimeofday test limits = 10000
        elpased(22) [time=0.000022]
gettimeofday test limits = 1000
        elpased(2) [time=0.000002]
gettimeofday test limits = 100
        elpased(1) [time=0.000001]
clock test limits = 100000000
        CLOCKS_PER_SEC=1000000
        elpased(183109) [clk1=375095, clk2=558204]
clock test limits = 1000000
        CLOCKS_PER_SEC=1000000
        elpased(1795) [clk1=558251, clk2=560046]
clock test limits = 10000
        CLOCKS_PER_SEC=1000000
        elpased(29) [clk1=560054, clk2=560083]
clock test limits = 1000
        CLOCKS_PER_SEC=1000000
        elpased(2) [clk1=560089, clk2=560091]
clock test limits = 100
        CLOCKS_PER_SEC=1000000
        elpased(0) [clk1=560096, clk2=560096]
clock_gettime test limits = 100000000
        elpased(173184980) [start=3012.610434665 end=3012.610434665]
clock_gettime test limits = 1000000
        elpased(1761542) [start=3012.783671238 end=3012.783671238]
clock_gettime test limits = 1000
        elpased(2169) [start=3012.785437408 end=3012.785437408]
clock_gettime test limits = 100
        elpased(236) [start=3012.785444798 end=3012.785444798]

3 Test Code

如下是benchmark-time.c代码:

#include <errno.h>
#include <stdio.h>
#include <string.h>
#include <time.h>
#include <unistd.h>
#include <sys/time.h>

unsigned long val_tsc2microsec, val_systemcall;

void cpu_burst(unsigned long limits)
{
        unsigned long i;
        volatile int x = 0;

        if (!limits)
                limits = 1000*1000*100;

        for (i = 0; i < limits; ++i) {
                x += i;
        }

        (void)x;
}

#define T2M(tsc) ({ struct timeval tv; tsc2microsec((tsc), &tv); tv; })
void tsc2microsec(unsigned long tsc, struct timeval *tv)
{
        unsigned long microsec = tsc/val_tsc2microsec;
        tv->tv_sec = microsec/(1000*1000);
        tv->tv_usec = microsec%(1000*1000);
}

static __always_inline unsigned long rdtsc_ordered(void)
{
        unsigned long low, high;

        asm volatile("mfence\n\tlfence\n\t" ::: "memory");
        asm volatile("rdtsc" : "=a" (low), "=d" (high));

        return low | (high << 32);
}

void init_tsc_time()
{
        struct timeval tv1, tv2;
        unsigned long start, end, val, microsec, idx;

        printf("init TSC to microsecond (about 2 seconds)\n");

        for (val = 0, idx = 0; idx < 1000; ++idx) {
                start = rdtsc_ordered();
                gettimeofday(&tv1, NULL);
                end = rdtsc_ordered();
                (void)tv1;
                val += end - start;
        }
        printf("\t1000 system call tsc = %lu\n", val);
        val_systemcall = val/1000;

        gettimeofday(&tv1, NULL);
        start = rdtsc_ordered();
        sleep(2);
        end = rdtsc_ordered();
        gettimeofday(&tv2, NULL);

        microsec = (tv2.tv_sec - tv1.tv_sec)*1000*1000;
        if (tv2.tv_usec < tv1.tv_usec) {
                tv2.tv_usec += 1000*1000;
                microsec -= 1000*1000;
        }

        microsec += tv2.tv_usec - tv1.tv_usec;
        val_tsc2microsec = (end - start)/microsec;

        printf("\ttsc2microsec=%lu system_call=%lu [tsc=%lu, millisecond=%lu]\n",
               val_tsc2microsec, val_systemcall, (end - start), microsec);
}

void rdtsc_test(unsigned long limits)
{
        unsigned long start, end;
        struct timeval tv;

        printf("rdtsc test limits = %lu\n", limits);

        start = rdtsc_ordered();
        cpu_burst(limits);
        end = rdtsc_ordered();
        tsc2microsec(end - start, &tv);

        printf("\telpased(%lu) [start=%lu, end=%lu, time=%lu.%06lu]\n",
               end - start, start, end,
               tv.tv_sec, tv.tv_usec);
}

void gettimeofday_test(unsigned long limits)
{
        struct timeval tv1, tv2;
        unsigned long microsec;

        printf("gettimeofday test limits = %lu\n", limits);

        gettimeofday(&tv1, NULL);
        cpu_burst(limits);
        gettimeofday(&tv2, NULL);

        microsec = (tv2.tv_sec - tv1.tv_sec)*1000*1000;
        microsec += tv2.tv_usec;
        microsec -= tv1.tv_usec;
        microsec -= (val_systemcall*2)/val_tsc2microsec;

        printf("\telpased(%lu) [time=%lu.%06lu]\n",
               microsec, microsec/1000/1000, microsec);
}

void clock_test(unsigned long limits)
{
        clock_t clk1, clk2;

        printf("clock test limits = %lu\n", limits);

        clk1 = clock();
        cpu_burst(limits);
        clk2 = clock();

        printf("\tCLOCKS_PER_SEC=%lu\n", CLOCKS_PER_SEC);
        printf("\telpased(%lu) [clk1=%lu, clk2=%lu]\n",
               clk2 - clk1, clk1, clk2);
}

#define CLOCK_GETX_EXEC_CHECK(func, arg1, arg2) \
        ({                                              \
        int ret = func(arg1, arg2);                     \
        if (ret)                                        \
                fprintf(stderr, "%s error(%d,%s)",      \
                        #func, ret, strerror(errno));   \
        ret; })

void clock_gettime_test(unsigned long limits)
{
        struct timespec ts1, ts2;
        unsigned long v;

        printf("clock_gettime test limits = %lu\n", limits);

        CLOCK_GETX_EXEC_CHECK(clock_gettime,CLOCK_MONOTONIC, &ts1);
        cpu_burst(limits);
        CLOCK_GETX_EXEC_CHECK(clock_gettime,CLOCK_MONOTONIC, &ts2);

        v = (ts2.tv_sec - ts1.tv_sec)*1000*1000*1000;
        v += ts2.tv_nsec;
        v -= ts1.tv_nsec;

        printf("\telpased(%lu) [start=%lu.%09lu end=%lu.%09lu]\n",
               v, ts1.tv_sec, ts1.tv_nsec, ts1.tv_sec, ts1.tv_nsec);
}

int main()
{
        init_tsc_time();

        rdtsc_test(1000*1000*100);
        rdtsc_test(1000*1000);
        rdtsc_test(1000*10);
        rdtsc_test(1000);
        rdtsc_test(100);

        gettimeofday_test(1000*1000*100);
        gettimeofday_test(1000*1000);
        gettimeofday_test(1000*10);
        gettimeofday_test(1000);
        gettimeofday_test(100);

        clock_test(1000*1000*100);
        clock_test(1000*1000);
        clock_test(1000*10);
        clock_test(1000);
        clock_test(100);

        clock_gettime_test(1000*1000*100);
        clock_gettime_test(1000*1000);
        clock_gettime_test(1000 );
        clock_gettime_test(100);

        return 0;
}

4 参考资源