【问题标题】:Why does my logging library cause performance tests to run faster?为什么我的日志库会导致性能测试运行得更快?
【发布时间】:2015-07-21 01:11:17
【问题描述】:

在过去的一年中,我一直在用 C++ 开发一个日志库,并考虑到了性能。为了评估性能,我开发了a set of benchmarks 来将我的代码与其他库进行比较,包括根本不执行日志记录的基本案例。

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

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

我知道我应该尝试将其隔离为一个更简单的情况,而不是询问一个 4000 行的程序。但是有很多地方可以删除什么,如果没有假设,当我试图隔离它时,我只会让问题消失。我可能会再花一年的时间来做这件事。我希望 Stack Overflow 的集体专业知识能让这个问题变得更加浅显,或者对于比我更有经验的人来说原因是显而易见的。

关于我的库和基准测试的一些事实:

  • 该库由将日志参数推送到无锁队列 (Boost.Lockless) 的前端 API 和执行字符串格式化并将日志条目写入磁盘的后端线程组成。
  • 计时基于在程序开始和结束时简单地调用std::chrono::steady_clock::now(),并打印差异。
  • 基准测试在 4 核 Intel CPU (i7-3770K) 上运行。
  • 基准程序计算 1024x1024 的 Mandelbrot 分形并记录有关每个像素的统计信息,即它会写入大约一百万条日志条目。
  • 单工作线程案例的总运行时间约为 35 秒。所以速度提升约 1.5%。
  • 基准测试生成一个包含生成的 Mandelbrot 分形的输出文件(这不是定时代码的一部分)。我已验证在打开和关闭日志记录时会产生相同的输出。
  • 基准测试运行 100 次(使用所有基准测试库,这大约需要 10 小时)。条形图显示平均时间,误差线显示四分位距。
  • Source code for the Mandelbrot computation
  • Source code for the benchmark
  • Root of the code repository and documentation

我的问题是,我如何解释启用日志记录库后明显的速度增加?

编辑:在尝试了 cmets 中给出的建议后解决了这个问题。我的日志对象是在line 24 of the benchmark test 上创建的。显然,当 LOG_INIT() 触及日志对象时,它会触发页面错误,导致图像缓冲区的部分或全部页面映射到物理内存。我仍然不确定为什么这会将性能提高近半秒;即使没有日志对象,在 mandelbrot_thread() 函数中发生的第一件事就是写入图像缓冲区的底部,这应该具有类似的效果。但是,无论如何,在开始基准测试之前使用 memset() 清除缓冲区会使一切变得更加理智。当前的基准是here

我尝试过的其他事情是:

  • 使用 oprofile 分析器运行它。我永远无法让它在锁中注册任何时间,即使在扩大作业以使其运行大约 10 分钟之后也是如此。几乎所有时间都在 Mandelbrot 计算的内部循环中。但是,既然我知道了页面错误,也许我可以对它们进行不同的解释。我没有考虑检查图像写入是否花费了不成比例的时间。
  • 卸下锁。这确实对性能产生了显着影响,但结果仍然很奇怪,无论如何我无法对任何多线程变体进行更改。
  • 比较生成的汇编代码。存在差异,但日志构建显然做了更多的事情。没有什么能成为明显的性能杀手。

【问题讨论】:

  • 首先,您是否尝试过分析不同的测试并查看实际差异可能在哪里?这是我的第一个建议。我的第二个是公认的猜测,但这很容易:memset() 你的sample_buffer 在你启动计时器之前。我见过在第一次访问未初始化的内存时出现页面错误的实例。
  • 我注意到的另一件事是,在跨线程计算 mandelbrot 时确实有一些锁。虽然我没有尝试过多地分解您的逻辑,但您的日志记录实际上可能会以一种减少争用的幸运方式减慢单个线程。当两个或多个线程尝试进入同一个临界区时,暂停它们可能会很昂贵,因此您的记录器可能会以某种方式减慢速度,而幸运的是减少了两个线程同时尝试进入同一个临界区的几率.
  • 感谢 Andrew 和 Ike 的意见。在接下来的几天里,我将尝试您提出的所有建议。关于线程争用的cmets,请注意当我只有一个工作线程时效果最显着。在这种情况下,不应该对锁进行争用。但我会尝试完全移除锁。我还没有为这种特殊情况运行分析器,因为我假设所有的 CPU 时间都将归因于我的一个 mandelbrot() 函数,这不会很有帮助。但也许我能从中找到一些线索。
  • @AndrewHenle 你猜对了 memset() !如果您将其作为答案,我会将其标记为解决方案。感谢 Andrew 和 Ike 的出色建议。在我的更新中查看有关该解决方案的更多信息。
  • 请将您的解决方案作为答案发布并标记为已接受。

标签: c++ multithreading performance


【解决方案1】:

当第一次访问未初始化的内存时,页面错误会影响时序。

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

【讨论】:

    猜你喜欢
    • 1970-01-01
    • 1970-01-01
    • 1970-01-01
    • 2012-09-22
    • 2012-07-13
    • 1970-01-01
    • 2011-04-22
    • 1970-01-01
    • 1970-01-01
    相关资源
    最近更新 更多