使用gprof的怪异分析输出(Weird profiling output using gprof)

我目前剖析我的代码，这是C99标准，使用gprof。 我的计划是递归定义 。 我用gcc与启用了一些警告，并没有优化标志的-pg标志进行编译。 然后我运行的代码，然后命令：

gprof ./myProgram > outputFile.txt

我以什么输出告诉我很困惑，虽然。 这是说，我花了很多时间在这我知道一个事实，我没有花很多时间的函数。有问题的功能有内循环和执行任务的时间定数。 这是一个很小的任务，不过，通过增加时间的任务，比如说，从完成5-100我得到的时间采取我的程序执行总量没有明显变化的数量。 然而，gprof的告诉我，我已经在这个函数花费的执行时间近50％。

我不知道是什么问题就在这里。 有没有人遇到这样的事情之前？ 我能解决这个我自己？ 我使用的Linux CentOS的分布。 我曾试图安装OProfile的为不同的探查，但没有到/ usr /本地写访问，所以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告诉他们，到小数点后四位。 我使用随机暂停和检查堆栈。

首先， gprof是“CPU仿形”。 在IO，互斥，分页这意味着，或任何其它封闭的系统调用，它被关闭 ，并且不指望那个时候。 你说你正在做这样的事，但它可能在内心深处的一些库函数发生。 如果是这样， gprof面具吧。 在另一方面，单栈的样本将显示它正在等待，以概率相等的时候它正在等待分数。

其次，@keshlam说，了解有关“自我时间”是很重要的。 如果它是高，这意味着程序计数器在日常中发现的CPU时间的好个百分点。 但是，如果它是低的，这并不意味着该功能是无罪的。 该功能可以花费大量的时间，但通过调用子函数这样做。 一看就知道，你需要gprof “总”一栏，但作为总时间的百分比，而不是每次通话的绝对时间，这是它给你。 如果你把一个堆栈样本，那么任何程序将出现在它的概率等于一次被消费的比例。 更重要的是，你就会知道到底为什么时间被消耗，因为样品会显示在通话发生的确切行号。

增加： gprof尝试处理递归函数，但由于其作者所指出的，它不会成功。 然而，堆栈样品有递归没有问题。 如果堆叠样本递归函数调用期间拍摄，功能出现不止一次的堆栈，可能很多倍。 但是，它仍然是一个函数，或任何一行代码调用一个函数的的包容性的时间成本，只是时间的比例是在栈上的情况。 看到这一点，假设取出样品以恒定的频率，总共M个样本，和一个特定的代码功能或行上它们中的分数出现F。 如果代码功能或线可以由不采取任何时间，诸如通过删除它，它周围的分支，或者其传递到一个无限快的处理器，则就没有暴露于被采样。 那么动感* F的样品上，它曾出现就会消失 ，由分数F.缩短执行时间

Answer 2:

“自我”时间就是时间这个函数的代码实际支出。 “累积”时间就是该函数以及任何调用功能（自加子女）所花费的时间。

需要注意的是百分比是衡量时间的百分比。 这是运行一个伟大的多次（比如你的函数b ）显然会影响运行时比只运行几次（你的一个功能更n1_jacobi_to_converge ）。 在它每次通话（花费的时间/call ）可能太小报告，但总还是可以显著性，可能仍然认为这是值得寻找各种方法来降低呼叫的数量和/或提高每次调用的效率。

警告：JIT稳定之前的测量是没有意义的。 而且因为JIT是不确定的，尤其但不是唯一的大型多线程应用程序，性能可能会相当显着的变化来看，即使Java代码不变运行。 采取多种测量通过，有足够的热身测量之前，甚至然后准备理智检查探查的建议，因为它们可能会产生误导。

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

（我花了很多时间来优化Apache的Xalan和它的IBM内部的后代在那里，我们也有代码生成参与进来，有它自己的nondeterminacies初始性能的改进很容易和明显;之后，它变得更加具有挑战性的！）

文章来源: Weird profiling output using gprof