C++性能分析（Google CPU Perf工具）究竟测量什么？

Question

我正在尝试使用Google Perf Tools来分析一些CPU密集型应用程序。这是一个统计计算，使用`ofstream'将每个步骤转储到文件中。我不是C++专家，所以我很难找到瓶颈。我的第一次尝试结果如下：

总共：857个样本 357 41.7% 41.7% 357 41.7% _write$UNIX2003 134 15.6% 57.3% 134 15.6% _exp$fenv_access_off 109 12.7% 70.0% 276 32.2% scythe::dnorm 103 12.0% 82.0% 103 12.0% _log$fenv_access_off 58 6.8% 88.8% 58 6.8% scythe::const_matrix_forward_iterator::operator* 37 4.3% 93.1% 37 4.3% scythe::matrix_forward_iterator::operator* 15 1.8% 94.9% 47 5.5% std::transform 13 1.5% 96.4% 486 56.7% SliceStep::DoStep 10 1.2% 97.5% 10 1.2% 0x0002726c 5 0.6% 98.1% 5 0.6% 0x000271c7 5 0.6% 98.7% 5 0.6% _write$NOCANCEL$UNIX2003

这让人感到惊讶，因为所有真正的计算都在SliceStep::DoStep中进行。"_write$UNIX2003"（我在哪里可以找到它的信息？）似乎来自写输出文件。现在，令我困惑的是，如果我注释掉所有的outfile << "text"语句并运行pprof，则95％位于，'_write$UNIX2003'消失了。但是，我的应用程序没有加速，总时间测量结果如此。整个过程的加速不到1％。

我错过了什么吗？

补充： 没有outfile <<语句的pprof输出如下：

总共：790个样本 205 25.9% 25.9％ 205 25.9％ _exp $ fenv_access_off 170 21.5％ 47.5％ 170 21.5％ _log $ fenv_access_off 162 20.5％ 68.0％ 437 55.3％ scythe :: dnorm 83 10.5％ 78.5％ 83 10.5％ scythe :: const_matrix_forward_iterator :: operator * 70 8.9％ 87.3％ 70 8.9％ scythe :: matrix_forward_iterator :: operator * 28 3.5％ 90.9％ 78 9.9％ std :: transform 26 3.3％ 94.2％ 26 3.3％ 0x00027262 12 1.5％ 95.7％ 12 1.5％ _write $ NOCANCEL $ UNIX2003 11 1.4％ 97.1％ 764 96.7％ SliceStep :: DoStep 9 1.1％ 98.2％ 9 1.1％ 0x00027253 6 0.8％ 99.0％ 6 0.8％ 0x000274a6

看起来和我预期的差不多，但我没有看到性能上的明显提升（在10秒计算中只有0.1秒）。代码本质上是：

ofstream outfile("out.txt");
for loop:
  SliceStep::DoStep()
  outfile << 'result'
outfile.close()

更新：我使用boost::timer进行计时，从分析器开始的地方开始计时，到它结束的地方结束。我不使用线程或任何高级操作。

- Tristan

---

你如何衡量程序的运行时间呢？ 针对两种配置，可以使用命令“time ./yourprogramm”。 你是否使用多线程？ - ebo

进行一次计时运行并测量系统/用户时间。分析器的数据表明，如果没有输出，您应该可以缩短40％的运行时间。最简单的解释是分析器的测量结果存在偏差。 - ebo

这一切都取决于用户。我所做的事情非常简单，我认为……文件一直处于打开状态是否有任何意义？ - Tristan

你实际上写出了多少数据？同时，请确保在一台没有其他任务的机器上运行分析，并在读取结果之前多次运行程序3或4次。 - Richard Corden

几年过去了，但对某些人可能仍有所帮助。你说你尝试过“注释掉”输出；这可能在分支、编译器优化等方面对最终执行造成很大影响。尝试一下：1. 保留指令但将输出重定向到 /dev/null 2. 禁用所有优化（-O0）。这些可能会让你更好地了解哪些部分需要更多时间。 - Narcolessico

Answer 1

根据我的评论：

从您的分析器中得到的数字表明，如果没有打印语句，程序应该快大约40％。

然而，运行时间几乎没有变化。

显然，其中一项测量必须是错误的。这意味着您需要进行更多和更好的测量。

首先，我建议使用另一个简单的工具：time命令。这应该让您对时间花费有个大致的了解。

如果结果仍不能确定，您需要更好的测试用例：

• 使用更大的问题
• 在测量之前进行预热。做一些循环，然后在同一进程中开始任何测量。

---

Tiristan：这全都是用户的问题。我正在做的非常简单，我认为......文件一直开着是否有任何意义？

这意味着分析器是错误的。

使用Python将100000行打印到控制台会导致类似于：

for i in xrange(100000):
    print i

控制台输出：

time python print.py
[...]
real    0m2.370s
user    0m0.156s
sys     0m0.232s

对比：

time python test.py > /dev/null

real    0m0.133s
user    0m0.116s
sys     0m0.008s

我的观点是： 你的内部测量和时间表明，禁用输出并没有带来任何好处。但Google Perf Tools认为应该这样做。谁错了呢？

- ebo

---

这个操作肯定需要10秒钟，基本上都在Slice::DoStep函数附近。我不明白为什么_write可以在完成了40%之后消失，而没有任何影响... - Tristan

这就是关键所在。必定有一个数字出错了。找出哪一个是错误的。性能分析器生成的数字可能不具备统计意义或者完全错误。 - ebo

Answer 2

_write$UNIX2003 可能是指 write POSIX 系统调用，它输出到终端。与几乎任何其他操作相比，I/O 的速度非常慢，因此如果您正在编写大量输出，则程序在这里花费了很多时间是有道理的。

我不确定为什么当您删除输出时，程序不会加速，但我无法根据您提供的信息进行猜测。看到一些代码，甚至是在 cout 语句被删除时的性能工具输出将是很好的。

- Tyler McHenry

Answer 3

Google perftools 收集调用栈的样本，所以你需要做的就是获得一些对它们的可见性。

根据文档，你可以按语句或地址粒度显示调用图。这应该告诉你你需要知道的内容。

- Mike Dunlavey