c++ - 由于配置文件部分之外的代码，使用clock_gettime()进行不合理的时间测量

Question

我正在使用下面的C程序(与gcc一起编译)来测量给定代码段的计算时间。
问题在于，当在之外的之外使用函数时，正在分析的代码段会在uleep()中获得不同的度量。

#include <unistd.h>
#include <stdio.h>
#include <time.h>

int main()
{
 int f = 0;
 while (f < 10)
 {
 double sum = 1.0;
 struct timespec t0, t1;

 clock_gettime(CLOCK_MONOTONIC, &t0);

 // CODE SECTION BEING PROFILED
 for (unsigned int i = 0; i < 5e6; i++)
 sum += 0.001;
 // END OF CODE SECTION BEING PROFILED

 clock_gettime(CLOCK_MONOTONIC, &t1);


 double elapsed_time = t1.tv_sec - t0.tv_sec;
 elapsed_time += (t1.tv_nsec - t0.tv_nsec) * 1e-9;

 printf("%.2f ms\n", elapsed_time*1000 );

 f++;

 // Sleep causing fake clock_gettime measurements?
 usleep(50000);
 }

 return 0;
}

下面，当对elapsed_time进行注释时，我粘贴程序的结果:
13.83毫秒
14.30毫秒
14.41毫秒
13.77毫秒
13.85毫秒
13.88毫秒
14.55毫秒
13.28毫秒
13.70毫秒
13.56毫秒
现在，出现uleep(50000)时的结果:
15.37毫秒
14.16毫秒
36.43毫秒
39.39毫秒
36.38毫秒
36.27毫秒
34.14毫秒
38.52毫秒
38.18毫秒
37.53 ms
我试图用uleep(50000)中的不同时钟来测量时间，也尝试使用C++ clock_gettime()来测量时间。但是，在所有情况下结果都是相似的。
此外，我尝试了不同的gcc标志，例如std::chrono::high_resolution_clock。在这种情况下，尽管获得的时间要短得多，但是当存在O2时，与不存在usleep()时相比，仍有一些测量值比〜3x 高。
我发现usleep()中使用的微秒数会影响最终的测量时间，例如用10000us我得到:
13.75毫秒
13.54毫秒
13.34毫秒
14.15毫秒
13.12毫秒
12.79毫秒
28.72毫秒
25.84毫秒
26.18毫秒
24.53毫秒
经过所有这些测试之后，我无法在该程序中找到导致这些“假”时间测量的原因。如果有人能对此问题提供一些帮助，我将不胜感激。
提前致谢!

编辑:
经过一些进一步的测试，我意识到usleep()引起了相同的问题(请参见下面的代码)。

#include <unistd.h>
#include <stdio.h>
#include <time.h>

int main()
{
    double total_time = 0.0;
    int f = 0;
    while (f < 1000)
    {
        double sum = 1.0;
        struct timespec t0, t1;

        clock_gettime(CLOCK_MONOTONIC, &t0);

        // Code section being profiled
        for (unsigned int i = 0; i < 5e6; i++)
            sum += 0.001;
        // End of Code section being profiled

        clock_gettime(CLOCK_MONOTONIC, &t1);


        double elapsed_time = t1.tv_sec - t0.tv_sec;
        elapsed_time += (t1.tv_nsec - t0.tv_nsec) * 1e-9;
        total_time += elapsed_time;


        f++;

        // Sleep/printf causing fake clock_gettime measurements?
        printf("%.2f ms\n", elapsed_time*1000 );
        // usleep(10000);
    }
    printf("TOTAL TIME: %.2f ms\n", total_time*1000 );
    return 0;
}

结果
当我运行用printf() f编译的代码时，总时间为:

〜13071.42 ms存在g++ -g行时的(注意，该行再次位于要分析的部分的外部)。

〜12712.22 ms ，当该行被注释时。

如果程序是使用优化(printf("%.2f ms\n", elapsed_time*1000 );)编译的，则我获得的总时间为:

〜3145.27毫秒(如果存在g++ -O2)。

〜2741.45毫秒(当该printf()不存在时)。

与printf()相比，使用printf()时，测量的时间增加的程度较小。因此，usleep()似乎不是导致此问题的唯一函数...
无论如何，对于放置在正在分析的代码部分之外的代码，所测量的时间不应受到影响...我是否缺少某些内容？

编辑2:
我尝试过的不同时钟是:usleep()，CLOCK_MONOTONIC_RAW和CLOCK_PROCESS_CPUTIME_ID。它们都提供相同的行为。
此外，我验证了CLOCK_REALTIME的返回值以丢弃失败。

Answer 1

您好像是CPU frequency scaling的受害者。

CPU频率缩放

您的CPU缩放驱动程序会根据各种因素来调节CPU频率，但重要的是根据当前的CPU负载来调节CPU频率。 Linux内核有各种可用的驱动程序，以及不同的缩放调节器。每个驱动程序都可以支持一组定标的调速器，并且根据当前 Activity 的调速器而表现不同。

例如，笔记本电脑上的默认驱动程序是intel_pstate，以及可用的调控器powersave和performance。如果将驱动程序更改为acpi-cpufreq，我还将获得ondemand，userspace和conservative。

不同调速器之间的主要区别在于它们的名称:powersave调速器将尝试使CPU保持较低的频率以节省功率，而performance调速器将尝试使CPU保持较高的频率以使运行更快。

在某些情况下，performance调控器仅将CPU频率固定为最大可用频率(对我来说，这就是intel_pstate驱动程序发生的情况)。在其他情况下，它只会尝试使其保持“高电平”，但仍会进行调整(对我来说，这就是acpi-cpufreq驱动程序发生的情况)。

无论如何，缩放驱动程序和调节器的组合可动态调节CPU频率，将考虑CPU负载，以便在可能的情况下即时进行频率调整。这可能在通过系统调用输入内核代码时发生，也可能在内核本身运行调度程序以重新调度当前正在运行的进程时在调度记号上发生。

怎么了？

您很可能结合使用缩放驱动程序和调节器来动态设置CPU频率。

当您的代码在不调用usleep()的情况下运行时，CPU负担很重，并且频率基本稳定。但是，如果您的代码调用usleep()，则将大大减少CPU负载，并且缩放驱动程序会降低CPU频率。到睡眠后内核将进程唤醒时，频率要低得多，并且在缩放驱动器意识到需要增强之前需要花费一些时间。如果您保持规律的睡眠时间，则驱动程序将永远没有足够的时间来重新调整频率备份，并且代码将运行得更慢。

这也适用于printf()，它需要进行write() syscall才能打印文本，并且几乎适用于所有其他syscall。在用户空间和内核空间之间切换会减慢该过程，从而使频率被缩放驱动器降低。对于某些系统调用(如clock_gettime())，不会发生这种情况，该调用已优化为在用户空间中运行，并且不需要上下文切换。

这是我的计算机上带有动态调节器(例如ondemand)的示例:



您可以清楚地看到，CPU频率在第一次运行时(没有usleep())卡在最大值，然后上下波动而没有足够的时间在第二次运行时稳定(使用usleep())。您实际上可以注意到，测试2的avg时间几乎是测试1的3倍。我的机器上的acpi-cpufreq和Governor performance也会发生这种情况。

解

如果您能够设置不同的缩放驱动程序/总督组合，以保持固定的CPU频率，则两个版本的代码在时序上不会有差异。

这是我的计算机上的另一个示例，其CPU频率为静态(例如，使用userspace调节器并手动设置固定速度):



如您所见，这两个测试大约在同一时间运行。

如果您无法设置其他缩放比例调节器，请尝试更改内核的缩放比例驱动程序。如果运行Debian或Ubuntu，则可能具有用于不同扩展驱动程序的可加载模块。

通过查看当前的内核配置，可以查看内核的可用缩放驱动程序和调控器:

cat /boot/config-$(uname -r) | grep FREQ

例如，我可以看到:

...
CONFIG_X86_PCC_CPUFREQ=m
CONFIG_X86_ACPI_CPUFREQ=m
...

其中 m表示“作为模块可用”(可通过​​ modprobe加载)，而 y表示“内置”。

然后，您可以尝试执行以下操作:

# Load acpi-cpufreq since we have CONFIG_X86_ACPI_CPUFREQ=m
sudo modprobe acpi_cpufreq 

# Switch driver
echo acpi-cpufreq | sudo tee /sys/devices/system/cpu/cpu*/cpufreq/scaling_driver

# Check available governors for the driver
cat /sys/devices/system/cpu/cpu*/cpufreq/scaling_available_governors

测试码

这是用于以上GIF的基准测试代码:

#define _GNU_SOURCE
#include <unistd.h>
#include <stdio.h>
#include <time.h>
#include <math.h>
#include <sched.h>
#include <sys/types.h>

/**
 * Marco Bonelli - 2020-03-02
 * https://stackoverflow.com/a/60481392/3889449
 *
 * Test the effect of different scaling governors on CPU frequency and
 * performance under:
 *
 *   1) Continuous heavy load.
 *   2) Intermittent and short heavy load.
 *
 * gcc -O3 scaling_governor_test.c -o test
 * ./test [N_RUNS] [N_CYCLES_PER_RUN] [TEST2_DELAY_US]
 */

#define DEFAULT_RUNS   1000
#define DEFAULT_CYCLES 1000 * 1000
#define DEFAULT_DELAY  100 * 1000

// Don't optimize this as GCC would basically trash the whole function.
#pragma GCC push_options
#pragma GCC optimize("O0")
void __attribute__ ((noinline)) func(unsigned n) {
    double sum = 1.0;

    for (unsigned i = 0; i < n; i++)
        sum += 0.001;
}
#pragma GCC pop_options

void warmup(unsigned runs, unsigned cycles) {
    for (unsigned n = 1; n <= runs; n++)
        func(cycles);
}

double bench(unsigned n) {
    struct timespec t0, t1;

    clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &t0);
    func(n);
    clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &t1);

    return (t1.tv_sec - t0.tv_sec)*1000.0L + (t1.tv_nsec - t0.tv_nsec)/1000.0L/1000.0L;
}

void setup_affinity(void) {
    cpu_set_t set;

    CPU_ZERO(&set);
    CPU_SET(0, &set);

    if (geteuid() == 0) {
        if (sched_setaffinity(0, sizeof(set), &set) == 0)
            puts("Affinity set to CPU #0.");
        else
            perror("sched_setaffinity");
    } else {
        puts("Running as normal user, run as root to set CPU affinity.");
    }
}

int main(int argc, char **argv) {
    unsigned runs, cycles, delay;
    double cur, tot1, tot2, min, max, avg;

    if (argc < 2 || sscanf(argv[1], "%i", &runs) != 1 || runs < 1)
        runs = DEFAULT_RUNS;

    if (argc < 3 || sscanf(argv[2], "%i", &cycles) != 1 || cycles < 1)
        cycles = DEFAULT_CYCLES;

    if (argc < 4 || sscanf(argv[3], "%i", &delay) != 1 || delay < 1)
        delay = DEFAULT_DELAY;

    setup_affinity();

    printf("Benchmarking %u runs of %u cycles each.\n", runs, cycles);
    printf("Test #1 will proceed normally.\nTest #2 will usleep(%u) before each run.\n", delay);
    fputs("Warming up... ", stdout);
    fflush(stdout);

    warmup(10, cycles);

    puts("done.\n---");

    tot1 = 0;
    min = INFINITY;
    max = -INFINITY;

    for (unsigned n = 1; n <= runs; n++) {
        cur = bench(cycles);

        tot1 += cur;
        avg = tot1 / n;
        if (cur < min) min = cur;
        if (cur > max) max = cur;

        printf("\rTest #1: tot %-9.3f  avg %-7.3f  min %-7.3f  max %-7.3f [ms]", tot1, avg, min, max);
        fflush(stdout);
    }

    putchar('\n');

    tot2 = 0;
    min = INFINITY;
    max = -INFINITY;

    for (unsigned n = 1; n <= runs; n++) {
        usleep(delay);
        cur = bench(cycles);

        tot2 += cur;
        avg = tot2 / n;
        if (cur < min) min = cur;
        if (cur > max) max = cur;

        printf("\rTest #2: tot %-9.3f  avg %-7.3f  min %-7.3f  max %-7.3f [ms]", tot2, avg, min, max);
        fflush(stdout);
    }

    puts("\n---");

    if (tot1 < tot2)
        printf("Test #2 ran ~%.3fx slower than Test #1.\n", tot2/tot1);
    else if (tot1 > tot2)
        printf("Test #1 ran ~%.3fx slower than Test #2.\n", tot1/tot2);
    else
        puts("Reality is a simulation.");

    if (avg < 0.5)
        puts("Such low average times are not a good indicator. You should re-run the rest with different parameters.");

    return 0;
}