使用 gprof 进行奇怪的分析输出

Posted 2023-03-06

【中文标题】使用 gprof 进行奇怪的分析输出

【英文标题】：Weird profiling output using gprof

【发布时间】：2014-02-04 21:00:36

【问题描述】：

我目前正在使用 gprof 分析符合 C99 的代码。 我的程序是递归定义的。我正在使用带有 -pg 标志的 gcc 进行编译，并启用了一些警告，并且没有优化标志。然后我运行代码，然后是命令：

gprof ./myProgram > outputFile.txt

不过，我对输出告诉我的内容感到非常困惑。这是说我在一个我知道的一个函数上花了很多时间，而事实上我并没有花很多时间。有问题的函数内部有一个循环，并执行了一定次数的任务。不过，这是一个很小的任务，并且通过将任务完成的次数从 5 次增加到 100 次，我的程序执行所花费的总时间没有明显变化。但是，gprof 告诉我，我已经在这个函数中花费了将近 50% 的执行时间。

我不知道这里有什么问题。有没有人遇到过这样的事情？我可以自己解决这个问题吗？我正在使用 Linux 的 CentOS 发行版。我尝试将 OProfile 安装为不同的分析器，但没有对 /usr/local 的写入权限，因此 make install 失败，所以不确定这是否只是 gprof 的问题

这里是输出文件的相关部分。奇怪的输出是函数nl_jacobi_to_converge：

从我拥有的平面轮廓

  %   cumulative   self              self     total           
 time   seconds   seconds    calls   s/call   s/call  name    
 49.02      7.50     7.50     1562     0.00     0.01  calculate_resid_numeric_jac_diags_tc41
 16.41     10.01     2.51 323878716     0.00     0.00  c
 14.97     12.30     2.29 323878716     0.00     0.00  b
  6.01     13.22     0.92       89     0.01     0.02  calculate_resid_tc41
  5.69     14.09     0.87 10967082     0.00     0.00  rhs_function
  1.11     14.26     0.17     1562     0.00     0.00  single_nl_jacobi
  ...
  0.00     15.30     0.00       11     0.00     0.76  nl_jacobi_to_converge

从我的粒度来看

index % time    self  children    called     name
                0.00    8.32      11/11          nl_multigrid [3]
[5]     54.4    0.00    8.32      11         nl_jacobi_to_converge [5]
                5.28    2.92    1100/1562        calculate_resid_numeric_jac_diags_tc41 [4]
                0.12    0.00    1100/1562        single_nl_jacobi [17]

【问题讨论】：

粘贴输出文件的基本部分会有所帮助。

@Chiel 我已经从文件中添加了一些额外的信息。函数 nl_jacobi_to_converge，虽然听起来在非常小的数据集上运行需要很长时间，但对整体运行时间应该没有影响

正如wikipedia 中所说的“gprof 方法（上下文不敏感的调用图）无法解决相互递归和非平凡循环”。所以，你可以试试gperftools的CPU profiler，它有完整的调用链记录（上下文相关）。

@osgx: Re: gperftools CPU profiler: 叹息——这么近却这么远。 1）如果它只在挂钟上采样，而不是 CPU 时间，它可以检测到不必要的阻塞时间。 2）如果每个堆栈样本的每个函数只计算一个“命中”，它将正确处理递归。 3）如果它只允许用户实际看到随机样本，他们可以看到代码行和函数摘要未暴露的其他问题。 4）如果用户可以更容易地限制采样，则样本集将与用户经历的时间相关。

【参考方案1】：

您是众多试图弄清楚gprof 告诉他们的内容的人之一，精确到小数点后四位。 I use random pausing and examining the stack.

首先，gprof 是一个“CPU 分析器”。 这意味着在 IO、互斥、分页或任何其他阻塞系统调用期间，它会关闭，并且不计算该时间。 你说你什么都没做，但它可能发生在某个库函数的深处。 如果是，gprof 会屏蔽它。 另一方面，单个堆栈样本将显示它正在等待什么，概率等于它等待的时间分数。

其次，正如@keshlam 所说，了解“自我时间”很重要。 如果它很高，这意味着在该例程中发现程序计数器占 CPU 时间的好百分比。 但是，如果它很低，这并不意味着该功能是无罪的。 该函数可能会花费 很多 时间，但通过调用子函数来完成。 要看到这一点，您需要gprof“total”列，但它是总时间的百分比，而不是每次调用的绝对时间，这就是它给你的。 如果你取一个堆栈样本，那么任何例程都会出现在它上面的概率等于它所花费的时间的一部分。 更重要的是，您将确切地知道为什么要花费这些时间，因为该示例将向您显示调用发生的确切行号。

添加：gprof 尝试处理递归函数，但正如其作者指出的那样，它没有成功。但是，堆栈样本在递归方面没有问题。如果在递归函数调用期间获取堆栈样本，则该函数在堆栈上出现多次，可能多次。但是，函数或调用函数的任何代码行的包含时间成本仍然只是它在堆栈上的时间的一部分。 为了看到这一点，假设以恒定频率采集样本，总共有 M 个样本，并且特定函数或代码行出现在其中的 F 部分。 如果可以使该函数或代码行不花时间，例如通过删除它、围绕它进行分支或将其传递给无限快的处理器，那么它就不会被采样。 然后它出现的 M*F 样本将消失，将执行时间缩短 F 部分。

【讨论】：

我对性能分析还很陌生，我自己从未检查过堆栈或堆。你能给我推荐一个工具来检查堆栈吗？我意识到这可能会涉及另一个问题，但我想对使用的好工具有一个快速的个人意见

Keeran Brabazon，gdb 或pstack 在 Linux 上。在 gdb 中执行：gdb --args ./yourprogram your args，然后是 run，然后在一段时间后按 Ctrl-C 停止。您可以使用backtrace 或where 命令查看堆栈，然后使用continue 继续执行。然后重复 Ctrl-C 几次。但我个人认为这个Poor Man's Profiler (poormansprofiler.org) 应该留在1980 年代。

@osgx：没问题，手动方法很粗糙。如果不是因为一件小事，我就不会那么讨厌它了——它会找到工具找到的任何东西，以及他们没有找到的东西，原因与调试器在没有人工操作的情况下无法找到错误的原因相同.

@MikeDunlavey 我遇到的问题是因为我的程序是递归定义的。我看到您在此处链接到的答案中解决了这个问题。我将更新我的问题中的描述以包含此信息。如果您可以在此处更新您的答案以快速说明 gprof 将为递归定义的代码提供奇怪的输出，那么我会将其作为接受的答案

【参考方案2】：

“自我”时间是实际花费在该函数代码中的时间。 “累积”时间是花在该函数和该函数调用的任何内容（自身加上孩子）上的时间。

请注意，百分比是测量时间的百分比。一个运行很多次的函数（比如你的b）显然比只运行几次的函数（你的n1_jacobi_to_converge）更能影响运行时间。每次通话花费的时间 (/call) 可能太小而无法报告，但总数仍然很重要，并且可能仍然表明值得寻找减少通话次数和/或提高每个通话效率的方法调用。

警告：JIT 稳定之前的测量是没有意义的。而且由于 JIT 是不确定的，尤其是但不仅限于大型多线程应用程序，因此即使 Java 代码未更改，每次运行的性能也可能会有很大差异。进行多次测量，在测量前进行足够的预热，即使这样，也要准备好检查分析器的建议，因为它们可能会产生误导。

另一个警告：检查是否正在测量信号量等待时间，并确保您知道所有线程中发生了什么。如果不计算等待，您可能会错过直接调用堆栈中没有的性能瓶颈。

（我花了很多时间优化 Apache Xalan 及其 IBM 内部的后代。在那里，我们还参与了代码生成，这有其自身的不确定性。最初的性能改进很容易而且很明显；之后它变得更具挑战性！）

【讨论】：

感谢您的建议，但问题是代码是顺序的、单线程的并且在 C 中。在我看来，分析器应该没有太多问题。我知道在 nl_jacobi_to_converge 中花费的时间很少，因为当我更改在此方法中执行的循环数（例如从 5 到 100）时，实际运行时间根本没有改变（time.h 中的时间无法选择提高运行时间的差异）。我确信调用了正确的代码，不知道如何解释 gprof 认为在这个方法上花费了这么多时间

该表同意您在该函数本身上花费的时间很少——自身时间为零，占总时间的百分比为零。该函数中的累积时间很高，这表明它调用的代码（包括间接调用）正在考虑该成本。深入研究。

请注意，瓶颈很可能是 I/O 之类的东西，在这种情况下，更改迭代次数（除非它也更改 I/O）不会对总时间产生太大影响。另一个想法是提防“第一次”初始化和此类风险。

没有 I/O。该函数中唯一的东西是一个调用子函数的 for 循环。我没有在这个函数中初始化任何东西。在这个方法中花费的累积时间应该不超过 0.1 秒，绝对是最大值，而且我所做的实验表明，在这个方法中改变循环次数对整体运行时间没有影响。我很困惑为什么分析器告诉我我在这里和子函数中花费时间

您可以通过注释掉这个函数的主体并查看执行时间是否下降来证明这一点。 “应该”可能只是意味着您忽略了某些东西，而“整体运行时间”可能包括这里根本没有考虑的时间。