【问题标题】:Large performance variability of fully CPU-bound code for no clear reason完全受 CPU 限制的代码的性能变化很大,原因不明
【发布时间】:2021-10-28 04:58:12
【问题描述】:

对于以下问题缺少最小可重现示例,我深表歉意。我将继续调查,如果我将其隔离为一小段代码,我会将这些信息添加到问题中。我真正在寻找的是新的调查途径,而不是准确的答案。

上下文

我编写了一些 C 代码,当在 gcc 下使用 -O3 编译时,在完全相同的硬件上从一次运行到下一次运行时间显示出相当大的差异,超过 15%。我不知道任何可能的跨运行变量来源,因为它是使用相同“输入”在相同硬件上运行的相同二进制文件(请参阅下面的几段)。

同样的效果出现在两个不同的板上。 我不是在比较各个方面的结果。问题是完全相同的代码运行时可变性超过 15%,由完全相同的编译器和优化选项编译成完全相同的二进制文件,在相同的硬件中运行,具有相同的输入。我只是表明这个问题,不管它是什么,并不局限于单个硬件。事实上,假设我只有下面两个板子之一——我仍然会问这个问题。

板是:

  • Nvidia Jetson Nano,4 x Cortex-A57 @ 1.479 GHz,gcc (Ubuntu/Linaro 7.5.0-3ubuntu1~18.04) 7.5.0
  • Raspberry Pi 4 型号 B,4 x Cortex-A72 @ 1.5 GHz,gcc (Ubuntu 10.3.0-1ubuntu1) 10.3.0

我使用 Google Benchmark 来测量时间 - 但是请注意,在独立运行代码(没有 Google Benchmark)、在循环内以及使用 time shell 命令进行时间时,可变性不会消失。

代码完全受 CPU 限制(一种加密算法)。代码是完全确定的:使用了一个伪随机数生成器,但它总是初始化为同一个种子。工作集可能适合 L1 D-cache,当然也适合 L2 缓存。代码完全不执行任何 I/O。

在没有优化的情况下编译代码时,两个板上的时序非常可重复。无论有没有优化,使用 clang 的时间也是非常可重复的。 Clang 版本是:

  • clang version 10.0.0-4ubuntu1~18.04.2 在 Jetson Nano 中
  • 树莓派中的Ubuntu clang version 12.0.0-3ubuntu1~21.04.1

因此,可变性只发生在 gcc、-O3 优化、两个不同的板和两个不同版本的 gcc。

作为参考,这是 Jetson Nano 板中使用 gcc 和 -O3 优化编译的版本的基准测试重复 30 次的日志:

--------------------------------------------------------------
Benchmark                    Time             CPU   Iterations
--------------------------------------------------------------
XXXXXXXXXXXX               433 us          432 us         1628
XXXXXXXXXXXX               431 us          430 us         1628
XXXXXXXXXXXX               418 us          417 us         1628
XXXXXXXXXXXX               414 us          413 us         1628
XXXXXXXXXXXX               414 us          414 us         1628
XXXXXXXXXXXX               414 us          413 us         1628
XXXXXXXXXXXX               389 us          388 us         1628
XXXXXXXXXXXX               366 us          366 us         1628
XXXXXXXXXXXX               366 us          365 us         1628
XXXXXXXXXXXX               367 us          366 us         1628
XXXXXXXXXXXX               368 us          367 us         1628
XXXXXXXXXXXX               366 us          365 us         1628
XXXXXXXXXXXX               366 us          365 us         1628
XXXXXXXXXXXX               366 us          365 us         1628
XXXXXXXXXXXX               366 us          365 us         1628
XXXXXXXXXXXX               366 us          365 us         1628
XXXXXXXXXXXX               367 us          366 us         1628
XXXXXXXXXXXX               366 us          365 us         1628
XXXXXXXXXXXX               366 us          365 us         1628
XXXXXXXXXXXX               366 us          366 us         1628
XXXXXXXXXXXX               366 us          366 us         1628
XXXXXXXXXXXX               366 us          366 us         1628
XXXXXXXXXXXX               366 us          366 us         1628
XXXXXXXXXXXX               366 us          365 us         1628
XXXXXXXXXXXX               366 us          366 us         1628
XXXXXXXXXXXX               366 us          366 us         1628
XXXXXXXXXXXX               366 us          366 us         1628
XXXXXXXXXXXX               366 us          365 us         1628
XXXXXXXXXXXX               366 us          365 us         1628
XXXXXXXXXXXX               366 us          366 us         1628
XXXXXXXXXXXX_mean          378 us          377 us           30
XXXXXXXXXXXX_median        366 us          366 us           30
XXXXXXXXXXXX_stddev       22.4 us         22.4 us           30

请注意,有些运行的所有时间都接近 430 us,而在接下来的运行中,所有时间都接近 365 us,以及开始较慢和完成较快的运行,如图所示。获得接近 415 us、400 us 和 380 us 的值也是典型的。 Raspberry Pi 4 板中的行为非常相似。

编辑:根据 cmets 部分的要求,这是一个固定 10,000 次迭代的运行:

-------------------------------------------------------------------------------
Benchmark                                     Time             CPU   Iterations
-------------------------------------------------------------------------------
XXXXXXXXXXXX/iterations:10000               421 us          421 us        10000
XXXXXXXXXXXX/iterations:10000               421 us          421 us        10000
XXXXXXXXXXXX/iterations:10000               421 us          421 us        10000
XXXXXXXXXXXX/iterations:10000               421 us          421 us        10000
XXXXXXXXXXXX/iterations:10000               420 us          420 us        10000
XXXXXXXXXXXX/iterations:10000               420 us          420 us        10000
XXXXXXXXXXXX/iterations:10000               398 us          398 us        10000
XXXXXXXXXXXX/iterations:10000               372 us          372 us        10000
XXXXXXXXXXXX/iterations:10000               372 us          372 us        10000
XXXXXXXXXXXX/iterations:10000               372 us          372 us        10000
XXXXXXXXXXXX/iterations:10000_mean          404 us          404 us           10
XXXXXXXXXXXX/iterations:10000_median        420 us          420 us           10
XXXXXXXXXXXX/iterations:10000_stddev       23.0 us         23.0 us           10

结束编辑

作为参考,这是在同一个板上运行,带有 clang 和 -O3 优化:

--------------------------------------------------------------
Benchmark                    Time             CPU   Iterations
--------------------------------------------------------------
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          256 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX               257 us          256 us         2726
XXXXXXXXXXXX               257 us          257 us         2726
XXXXXXXXXXXX_mean          257 us          257 us           30
XXXXXXXXXXXX_median        257 us          257 us           30
XXXXXXXXXXXX_stddev      0.092 us        0.063 us           30

经过几十次运行,结果总是非常相似,相差不超过 1 us 左右。

调查的因素

  1. 上面的结果只是动态电压频率缩放/涡轮增压/节流或类似效果的尖叫。这是调查的第一个途径。在 Jetson Nano 中,我使用 nvpmodel 实用程序来选择 MAXN (10 W) 设置,并使用 jetson_clocks 脚本来强制使用最大可能的 CPU 时钟。我还使用cpufrequtils 包中的cpufreq-set 将缩放调节器覆盖为performance。我使用jetson-stats 软件包中的jtop 实用程序监控CPU 时钟、温度和风扇速度。我从未见过任何可能的节流迹象。如果有更可靠的方法来读取节流状态和 CPU 频率,我很高兴知道。

编辑:我认为几乎可以排除节流。我安装了一个kernel module 以允许从用户空间读取pmccntr_el0 循环计数器(确保最小开销),并为函数的每次执行计时(即Google Benchmark 运行的数千次迭代中的每一次)的循环计数。然后我在 Raspberry Pi 上运行了两次。

在第一次运行中,Google Benchmark 测量了 372 微秒,从中可以预期 372e-6 * 1.5e9 = 558,000 个周期,实际上几乎所有的周期计数器测量值都在这个值附近徘徊(第一次运行,正如人们所期望的那样,需要更长的时间,接近 800,000 次循环,但 Google Benchmark 在实际测量之前会先进行“试运行”,因此甚至没有考虑到这一点。

在第二次运行中,Google Benchmark 测量了 421 us,从中可以预期 421e-6 * 1.5e9 = 631,500 个周期,并且几乎所有周期计数器测量值都徘徊在这个值附近。

更准确地说,第一次运行的平均值是 558,420 个周期,标准差是 9,536 个周期。第二次运行的平均值为 631,180 个周期,标准偏差为 4,431 个周期。即使考虑最大的标准差(从第一次运行开始),这也几乎是两个平均值之间差值的 8 个标准差,因此绝对具有统计显着性。

结束编辑

  1. 一个相关问题是由于电压不足而导致的节流,即 PSU 功率不足。过去我在使用 Jetson Nano 时遇到过这个问题,并购买了真正的三星 25 W USB-C 旅行充电器,能够输出 5 V x 3 A(型号 EP-TA800XB),符合 Jetson Nano 的规格。这款充电器配有一根短的 USB-C 到 USB-C 电缆,可能不会使电压下降太多。这是几个月前的事了,自从更换 PSU 后,我再也没有看到过节流警告。但是,由于我现在正在无头运行 Jetson Nano,所以我不知道如何从命令行监控它——如果有人知道如何这样做,我将不胜感激。

    至于 Raspberry Pi,在进行实验时,我确实发现最初我使用的是功率不足的 PSU,vcgencmd command 使用 get_throttled 参数证实了这一点。然后,我切换到 MacBook Pro 的 85 W USB-C 电源,并监控了节流状态,并没有再次发生:运行vcgencmd get_throttled 的结果为零,无论我向其施加哪些负载。

    所以看起来也可以排除欠压导致的节流。

  2. 我尝试运行 perf 并收集采样的时间配置文件以及各种 PMU 事件,以尝试找到不同运行时与其中一个事件之间的相关性。没有显着的相关性。运行的指令数量始终相同(在百分之几的范围内)。缓存和分支预测未命中略有不同,但没有相关性,例如执行时间随着缓存/分支预测未命中的增加而增加。

  3. 我尝试使用 taskset 将进程固定到一个核心,但可变性仍然存在。

  4. 我尝试使用 nice -n -20(以 root 身份)运行该进程,但可变性仍然存在。

还有什么我可以尝试的想法吗?

编辑:一个最小的可重现示例

我终于设法创建了一个最小的可重现示例。对于在有关共享库的问题中没有包含非常重要的信息,我深表歉意,这将很快澄清。前往 MRE。

main.c:

int f();

int main() {
    for (int i = 0; i < 100000000; i++) {
        volatile int temp = f();
        (void) temp;
    }
    
    return 0;
}

f.c:

int f() {
    return 1337;
}

生成文件:

all: main-shared main-static

clean:
    rm -f *.so *.o main-shared main-static

main-shared: libf.so main.c
    gcc -o main-shared main.c libf.so -Wl,-rpath,`pwd`

main-static: f.o main.c
    gcc -o main-static main.c f.o

libf.so: f.c
    gcc -O3 -fPIC -rdynamic -shared f.c -o libf.so

f.o: f.c
    gcc -O3 -fPIC f.c -c -o f.o

这是一个典型的运行输出:

swineone@jetson-nano:~/repro$ make
gcc -O3 -fPIC -rdynamic -shared f.c -o libf.so
gcc -o main-shared main.c libf.so -Wl,-rpath,`pwd`
gcc -O3 -fPIC f.c -c -o f.o
gcc -o main-static main.c f.o
swineone@jetson-nano:~/repro$ time ./main-shared

real    0m0,883s
user    0m0,880s
sys 0m0,000s
swineone@jetson-nano:~/repro$ time ./main-shared

real    0m0,621s
user    0m0,612s
sys 0m0,004s
swineone@jetson-nano:~/repro$ time ./main-static

real    0m0,478s
user    0m0,476s
sys 0m0,000s
swineone@jetson-nano:~/repro$ time ./main-static

real    0m0,523s
user    0m0,520s
sys 0m0,000s
swineone@jetson-nano:~/repro$ time ./main-static

real    0m0,527s
user    0m0,520s
sys 0m0,004s
swineone@jetson-nano:~/repro$ time ./main-static

real    0m0,477s
user    0m0,472s
sys 0m0,004s
swineone@jetson-nano:~/repro$ time ./main-static

real    0m0,504s
user    0m0,500s
sys 0m0,000s

确实,我运行了time ./main-static 100 次,最小/最大执行时间为 477/530 毫秒。这比我想要的要高,但可能与较短的执行时间以及不可避免的其他正在运行的进程有关。但这仍然比共享库版本的 621/883 毫秒拆分要好得多。

考虑到这可能与较短的运行时间有关,我将主循环的迭代次数增加了十倍。问题仍然没有消失:

swineone@jetson-nano:~/repro$ time ./main-shared 

real    0m6,099s
user    0m6,088s
sys 0m0,000s
swineone@jetson-nano:~/repro$ time ./main-shared 

real    0m8,692s
user    0m8,672s
sys 0m0,000s

我也跑了time ./main-static 10 次。最小/最大运行时间为 4.754/5.332 秒。因此,结果似乎与迭代次数无关。

因此,问题似乎与共享库有关,但我仍然不清楚为什么会发生这种情况。希望这个 MRE 能帮助人们弄清楚发生了什么。

编辑:不知道为什么,但传递环境变量 LD_BIND_NOW 似乎消除了 Raspberry Pi 4 上的可变性,但在 Jetson Nano 上却没有。这也可以在链接时通过在链接时将-Wl,-znow 标志传递给 gcc 来实现。

【问题讨论】:

标签: c performance gcc arm


【解决方案1】:

您的操作系统可以更改时钟速度。最初,处理器以低时钟速度运行以保持低功耗。然后 CPU 真的被使用了,所以操作系统认为快速运行比功耗更重要并提高时钟速度。

【讨论】:

  • OP 的第 1 点解释说,他们已经(试图)通过覆盖缩放调节器来排除这种情况。
猜你喜欢
  • 1970-01-01
  • 1970-01-01
  • 1970-01-01
  • 1970-01-01
  • 1970-01-01
  • 2013-02-05
  • 2017-02-08
  • 2014-04-19
  • 2012-01-21
相关资源
最近更新 更多