对两个连续测量进行基准测试时不一致

Mar*_*rol 8 c++ linux performance caching performance-testing

我在对一个函数进行基准测试时,发现某些迭代比其他迭代慢。

经过一些测试后,我尝试对两个连续的测量进行基准测试,但仍然得到一些奇怪的结果。

代码在wandbox上

对我来说重要的是:

using clock = std::chrono::steady_clock;
// ...
for (int i = 0; i < statSize; i++)
{
    auto t1 = clock::now();
    auto t2 = clock::now();
}
Run Code Online (Sandbox Code Playgroud)

正如我们在Godbolt上看到的那样,该循环已被优化

call std::chrono::_V2::steady_clock::now()
mov r12, rax
call std::chrono::_V2::steady_clock::now()
Run Code Online (Sandbox Code Playgroud)

该代码使用以下代码进行编译:

g++  bench.cpp  -Wall  -Wextra -std=c++11 -O3
Run Code Online (Sandbox Code Playgroud)

gcc version 6.3.0 20170516 (Debian 6.3.0-18+deb9u1)安装在英特尔®至强®W-2195处理器上

我是计算机上的唯一用户,我尝试在没有优先级(nicechrt)的情况下运行,结果是相同的。

我经过1亿次迭代得到的结果是:

1亿次迭代

Y轴以纳秒为单位,是线的结果

std::chrono::duration_cast<std::chrono::nanoseconds>(t2 - t1).count()
Run Code Online (Sandbox Code Playgroud)

这4行让我想到:没有缓存/ L1 / L2 / L3缓存未命中(即使“ L3缓存未命中”行似乎与L2行距离太近)

我不确定为什么会出现缓存未命中,可能是结果的存储,但是它不在测量的代码中。

我已尝试使用1500循环运行10000次程序,因为此处理器的L1缓存为:

lscpu | grep L1 
L1d cache:             32K
L1i cache:             32K
Run Code Online (Sandbox Code Playgroud)

而且1500*16 bits = 24 000 bits它小于32K,因此不应有缓存未命中。

结果:

10000次循环1500次

我还有4条线(还有一些噪音)。

因此,如果确实是缓存未命中,我不知道为什么会发生。

我不知道它是否对您有用,但我运行:

sudo perf stat -e cache-misses,L1-dcache-load-misses,L1-dcache-load  ./a.out 1000
Run Code Online (Sandbox Code Playgroud)

具有价值 1 000 / 10 000 / 100 000 / 1 000 000

我得到了所有L1-dcache命中率的4.70%至4.30%,对我来说似乎很不错。

所以问题是:

  • 这些放缓的原因是什么?
  • 当我没有固定时间执行No操作时,如何生成函数的定性基准?

附言:我不知道我是否缺少有用的信息/标志,随时问!


繁殖方式

  1. 代码:

    #include <iostream>
    #include <chrono>
    #include <vector>
    
    int main(int argc, char **argv)
    {
        int statSize = 1000;
        using clock = std::chrono::steady_clock;
        if (argc == 2)
        {
            statSize = std::atoi(argv[1]);
        }
    
        std::vector<uint16_t> temps;
        temps.reserve(statSize);
        for (int i = 0; i < statSize; i++)
        {
    
            auto t1 = clock::now();
    
            auto t2 = clock::now();
    
            temps.push_back(
                std::chrono::duration_cast<std::chrono::nanoseconds>(t2 - t1).count());
        }
    
        for (auto t : temps)
            std::cout << (int)t << std::endl;
    
        return (0);
    }
    
    Run Code Online (Sandbox Code Playgroud)
  2. 建立:

    g++  bench.cpp  -Wall  -Wextra -std=c++11 -O3
    
    Run Code Online (Sandbox Code Playgroud)
  3. 生成输出(需要sudo):

    在这种情况下,我将运行10000次程序。每次采取100项措施,而我删除的第一种措施总是慢5倍:

     for i in {1..10000} ; do sudo nice -n -17 ./a.out 100 | tail -n 99  >> fast_1_000_000_uint16_100 ; done
    
    Run Code Online (Sandbox Code Playgroud)
  4. 生成图形:

    cat fast_1_000_000_uint16_100 | gnuplot -p -e "plot '<cat'"
    
    Run Code Online (Sandbox Code Playgroud)
  5. 我在机器上得到的结果是:

在此处输入图片说明


祖兰的回答和所有评论之后我在哪里

current_clocksource被设定在tsc与在没有开关看出dmesg,命令使用:

dmesg -T | grep tsc
Run Code Online (Sandbox Code Playgroud)

使用此脚本删除了超线程(HT),然后

grep -c proc /proc/cpuinfo
=> 18
Run Code Online (Sandbox Code Playgroud)

从最后的结果中减去1,以获得最后一个可用的核:

=> 17
Run Code Online (Sandbox Code Playgroud)

编辑/ etc / grub / default并在GRUB_CMDLINE_LINUX中添加isolcpus =(最后结果):

GRUB_CMDLINE_LINUX="isolcpus=17"
Run Code Online (Sandbox Code Playgroud)

结局:

sudo update-grub
reboot 
// reexecute the script
Run Code Online (Sandbox Code Playgroud)

现在我可以使用:

taskset -c 17 ./a.out XXXX
Run Code Online (Sandbox Code Playgroud)

因此,我运行了1万次,循环了100次迭代。

for i in {1..10000} ; do sudo /usr/bin/time -v taskset -c 17 ./a.out 100  > ./core17/run_$i 2>&1 ; done
Run Code Online (Sandbox Code Playgroud)

检查是否有Involuntary context switches

grep -L "Involuntary context switches: 0" result/* | wc -l
=> 0 
Run Code Online (Sandbox Code Playgroud)

没有,很好。让我们绘图:

for i in {1..10000} ; do cat ./core17/run_$i | head -n 99 >> ./no_switch_taskset ; done
cat no_switch_taskset | gnuplot -p -e "plot '<cat'"
Run Code Online (Sandbox Code Playgroud)

结果:

1000000中有22个失败(1000个或更多)

我不了解仍有22个大于1000的度量值(大多数值在20附近)。

下一步,待定

做部分:

sudo nice -n -17 perf record...
Run Code Online (Sandbox Code Playgroud)

祖兰答案的

Zul*_*lan 3

我无法用这些特定的聚集线来重现它,但这里有一些一般信息。

可能的原因

正如评论中所讨论的,在正常空闲系统上表现良好只是尽力而为。你至少还有

  1. 调度滴答定时器

  2. 绑定到特定代码的内核任务

  3. 您的任务可能因任意原因从一个核心迁移到另一个核心

您可以使用isolcpustaskset来获取某些进程的独占核心来避免其中的一些情况,但我认为您无法真正摆脱所有内核任务。另外,使用nohz=full禁用调度刻度。您还应该禁用超线程以从硬件线程获得对核心的独占访问。

除了taskset我绝对推荐用于任何性能衡量之外,这些都是非常不寻常的衡量标准。

测量而不是猜测

如果怀疑可能发生什么,您通常可以设置测量来证实或反驳该假设。perf跟踪点对此非常有用。例如,我们可以从查看调度活动和一些中断开始:

sudo nice -n -17 perf record -o perf.data -e sched:sched_switch -e irq:irq_handler_entry -e irq:softirq_entry ./a.out ...
Run Code Online (Sandbox Code Playgroud)

perf script现在将告诉您列出所有发生的情况。为了将其与 缓慢的迭代相关联,您可以使用perf probe稍微修改的基准:

void __attribute__((optimize("O0"))) record_slow(int64_t count)
{
    (void)count;
}

...

    auto count = std::chrono::duration_cast<std::chrono::nanoseconds>(t2 - t1).count();
    if (count > 100) {
        record_slow(count);
    }
    temps.push_back(count);
Run Code Online (Sandbox Code Playgroud)

并编译-g

sudo perf probe -x ./a.out record_slow count
Run Code Online (Sandbox Code Playgroud)

然后添加-e probe_a:record_slow到调用中perf record。现在如果你幸运的话,你会发现一些接近的事件,例如:

 a.out 14888 [005] 51213.829062:    irq:softirq_entry: vec=1 [action=TIMER]
 a.out 14888 [005] 51213.829068:  probe_a:record_slow: (559354aec479) count=9029
Run Code Online (Sandbox Code Playgroud)

请注意:虽然这些信息可能会解释您的一些观察结果,但您会进入一个充满更多令人费解的问题和奇怪现象的世界。此外,虽然perf开销相当低,但您的测量结果可能会受到一些干扰。

我们的基准测试是什么?

首先,你需要明确你实际衡量的是什么:执行时间std::chrono::steady_clock::now()。实际上,这样做至少可以弄清楚测量开销以及时钟的精度。

这实际上是一个棘手的点。此函数的成本如下clock_gettime所示,取决于您当前的时钟源1。如果那是tsc你的事,hpet那就慢得多。Linux 在运行期间可以悄悄地从2切换到2tschpet

怎样做才能得到稳定的结果?

有时您可能需要进行极端隔离的基准测试,但通常即使对于非常低级别的微架构基准测试也没有必要。相反,您可以使用统计效应:重复测量。使用适当的方法(均值、分位数),有时您可能希望排除异常值。

如果测量内核没有明显长于计时器精度,则您将必须重复内核并在外部进行测量以获得吞吐量而不是延迟,延迟可能会有所不同,也可能不会有所不同。

是的 - 基准测试非常复杂,您需要考虑很多方面,特别是当您更接近硬件并且内核时间变得非常短时。幸运的是,有一些帮助,例如谷歌的基准测试库在进行适量的重复以及实验因素方面提供了很多帮助。

1 /sys/devices/system/clocksource/clocksource0/current_clocksource

2实际上它dmesg就像这样

时钟源:CPU 上的计时看门狗:将时钟源“tsc”标记为不稳定,因为偏差太大: