为什么 gprof 显着低估了程序的运行时间？

Question

我有这个程序需要 2.34 秒才能运行，而 gprof 说它只需要 1.18 秒。我在其他地方读过的答案表明，如果程序是 I/O 绑定的，gprof 可能会出错，但这个程序显然不是。

这也发生在我尝试分析的有用程序上。它并不特定于这个琐碎的测试用例。

（同样在这种情况下，gprof 表示 main() 占用了程序运行时间的 100% 以上，这是一个非常愚蠢的错误，但对我来说并没有真正引起问题。）

$ cat test.c
int main() {
    int i;
    for (i=0;i<1000000000;i++);
}

$ gcc test.c -o test

$ time ./test

real    0m2.342s
user    0m2.340s
sys 0m0.000s

$ gcc test.c -o test -pg

$ time ./test

real    0m2.342s
user    0m2.340s
sys 0m0.000s

$ gprof test |head
Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  Ts/call  Ts/call  name    
101.33      1.18     1.18                             main

 %         the percentage of the total running time of the
time       program used by this function.

Answer 1

我建议放弃gprof 并切换到oprofile。任何将仪器插入程序的分析都会以可能扭曲或使结果无效的方式固有地影响性能。使用oprofile，您不必构建具有分析支持的程序或获取启用了分析的特殊库；它通过统计方法工作，基本上是对指令指针进行采样（在内核帮助下）并使用样本计数来估计每个函数花费了多少时间。

Answer 2

首先，分析一个在 2.3 秒内完成的程序有点可笑。您确实需要一个长时间运行的程序才能很好地测量程序热点等。但是我离题了...

要回答您的第一个问题，时间（命令行实用程序）乘以整个过程（包括分析工具本身）的执行时间。当您在构建中启用分析时，程序会在您每次运行程序时写入一个包含执行时间等的 gmon.out 文件。也就是说，每次运行程序时都会完成分析的艰苦工作。分析工具试图分离出它自己对时间核算的影响，在这种情况下，分析本身似乎占了运行时间的 2.34 - 1.18 = 1.16 秒（按时间报告）。 gprof 程序本身本质上只是分析和重新格式化存储在 gmon.out 程序中的运行时统计信息。要明确这一点，真正的分析发生在程序运行期间，而不是 gprof 运行期间。

最后，gprof 输出直接回答了您的第二个问题。它以 1/100 秒对您的程序执行进行采样。间隔并将整个 0.01 秒归功于样本期间发生的任何事情。如果您的程序执行时间不是 0.01 秒的精确倍数，那么您将得到的数字加起来不等于 100%。同样，必须强调的是，对运行如此之快的程序进行分析是很容易出错的，而且这个明显的错误肯定会通过更长的采样间隔（即运行时）来缓解。此外，gprof 对其自身开销的计算是不完善的，这可能会进一步导致看似荒谬的 101.33% 数字。

这是一个统计过程，并不完美。您必须对结果持保留态度。

祝你好运！

Answer 3

首先，回答您的问题，gprof 不计算阻塞时间，因此如果机器“同时”发生其他任何事情，您会看到这种差异。此外，如果您的程序执行任何 I/O，也不会计算在内。

gprof 实际上只对非常有限的一类程序有用。 Here is a list of the issues.