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

~$ 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

#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;
}