c - 使用 gprof 的奇怪分析输出

Question

我目前正在使用 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]

Answer 1

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

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

其次，正如 @keshlam 所说，了解“自拍时间”很重要。 如果它很高，则意味着在该例程中发现程序计数器占了 CPU 时间的很大一部分。 然而，如果它很低，并不意味着该函数没有问题。 该函数可能花费大量时间，但通过调用子函数来完成。 要看到这一点，您需要 gprof“total”列，但作为总时间的百分比，而不是它为您提供的每次调用的绝对时间。 如果您采取堆栈样本，则任何例程都会出现在其上，其概率等于其所花费的时间的分数。 此外，您将确切地知道为什么要花费这些时间，因为示例将向您显示发生调用的精确行号。

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