为什么我的日志库会导致性能测试运行得更快？

Question

在过去的一年里，我在C++中开发了一个日志库，考虑到了性能。为了评估性能，我开发了一套基准来比较我的代码和其他库，包括一个根本不执行日志记录的基本案例。

在我的上一个基准测试中，我测量了一个CPU密集型任务的总运行时间，而日志记录是活动的，而不是的。然后，我可以比较时间，以确定我的库有多少开销。这张条形图显示了与我的非日志记录基本情况相比的差异。

​

​

如您所见，我的库(“鲁莽”)增加了负开销(除非所有4个CPU内核都很忙)。当启用日志记录时，程序运行速度比禁用时快约半秒。

我知道我应该尝试把这个问题归结为一个更简单的情况，而不是询问4000行程序。但是有那么多的场所可以去除什么，没有一个假设，当我试图隔离它的时候，我只会让问题消失。我可能还能再花一年时间来做这个。我希望Stack溢出的集体专业知识会使这成为一个更肤浅的问题，或者对比我更有经验的人来说，原因是显而易见的。

关于我的图书馆和基准的一些事实：

• 该库由一个前端API组成，该API将日志参数推入一个无锁队列(Boost.Lockless)和一个执行字符串格式化并将日志条目写入磁盘的后端线程。
• 计时的基础是在程序开始和结束时简单地调用std::chrono::steady_clock::now()，然后打印差异。
• 基准运行在英特尔的4核CPU (i7-3770K)上。
• 基准程序计算一个1024x1024 Mandelbrot分形，并记录每个像素的统计信息，即它写了大约100万个日志条目。
• 对于单个工作线程情况，总运行时间约为35秒。所以提速大约是1.5%。
• 基准测试生成一个输出文件(这不是时间代码的一部分)，其中包含生成的Mandelbrot分形。我已经验证了在日志记录打开和关闭时会产生相同的输出。
• 基准测试运行100次(与所有基准库一起，这大约需要10个小时)。条形图显示平均时间，误差条显示四分位数范围。
• Mandelbrot计算的源代码
• 基准测试的源代码。
• 代码存储库和文档的根。

我的问题是，当启用日志库时，我如何解释明显的速度增长？

编辑：这是在尝试了在评论中给出的建议之后解决的。我的日志对象是在基准测试第24行上创建的。显然，当LOG_INIT()接触到日志对象时，它会触发一个页面错误，导致图像缓冲区的部分或所有页面被映射到物理内存。我仍然不知道为什么这会使性能提高近半秒；即使没有日志对象，mandelbrot_thread()函数中发生的第一件事就是写入图像缓冲区的底部，这应该有类似的效果。但是，无论如何，在启动基准测试之前，使用memset()清除缓冲区会使一切变得更加正常。当前的基准测试是这里

其他我尝试过的事情是：

• 用oprofile分析器运行它。我永远无法让它在锁中的任何时间注册，即使在扩展作业使其运行了大约10分钟之后。几乎所有的时间都在Mandelbrot计算的内部循环中。但是，既然我知道了页面错误，也许我就能对它们进行不同的解释了。我没有想过要检查一下图像书写是否花费了不成比例的时间。
• 拆下锁。这确实对性能有很大的影响，但结果仍然很奇怪，而且无论如何，我无法在任何多线程变体中进行更改。
• 比较生成的程序集代码。虽然有不同之处，但是日志构建显然在做更多的事情。没有什么比一个明显的性能杀手更突出了。

Answer 1

当第一次访问未初始化内存时，页面错误将影响定时。

因此，在第一次调用std::chrono::steady_clock::now()之前，通过在sample_buffer上运行memset()来初始化内存。