令人困惑的gprof输出

4

我在一个运行时间为16.637秒的C++程序上运行了gprof,根据time(),我得到了以下输出的第一行:

%   cumulative   self              self     total           
time   seconds   seconds    calls   s/call   s/call  name    
31.07      0.32     0.32  5498021     0.00     0.00  [whatever]

为什么它列出了31.07%的时间,而只花费了0.32秒?这是每次调用的时间吗?(那不会是自身s/call吗?)
这是我第一次使用gprof,请多多关照 :)
编辑:通过向下滚动,看起来gprof只认为我的程序需要1.03秒。为什么它会如此错误?
6个回答

9

没错。gprof 会忽略任何未被插装的代码,通常包括在 stdlib 和系统调用中花费的时间。获取 I/O 和分配绑定程序的准确分析信息可能会有些棘手。 - Chris Conway
我刚遇到了同样的问题。感谢您提供这个解决方案。 - Matt Joiner

6

自身时间是在[某事物]中花费的时间。

累计时间是在[某事物]和其上方调用的函数(例如[某事物]+主函数)中所花费的时间。

这两者都不包括从[某事物]中调用的函数所花费的时间。这就是为什么您没有看到更多时间列表。

如果您的[某事物]函数调用了大量的printf,那么您的gprof输出告诉您printf正在消耗大部分时间。


实际上,我有一个程序,其中一个函数没有调用其他函数,但仍然存在类似的问题。通过调整这个函数,比gprof建议的节省了更多的时间。 - casualcoder
百分比时间仅指在所讨论的函数中花费的时间。显然如此,否则"main"将成为每个gprof配置文件中的顶级函数。 - Sol

2
这篇如何阅读gprof输出的概述看起来相当不错。你看到的31.07%是gprof认为程序在该函数中花费的总运行时间的一部分(不包括它调用的函数)。很可能百分比这么高而时间这么短是因为gprof认为程序比您想象的快。您可以通过滚动gprof输出的第一部分来轻松地检查此事实:累计秒数将不断增加,直到它限制在程序的总运行时间(从gprof的角度来看)。我认为您会发现这大约是一秒钟,而不是您期望的16秒。
至于为什么会有这么大的差异,我无法说。也许gprof没有看到所有的代码。或者你在进行性能分析时使用了time。我不认为那会正确地工作...

我确实花了时间在有仪器的代码上,但我也在几次非有仪器的代码运行中进行了检查,结果相当接近(相差不到一秒)。 - Jesse Beder
你有没有像我建议的那样检查gprof以查看运行的总时间是多少? - Sol
是的,它是1.03秒。为什么会出现这么大的误差呢? - Jesse Beder

1

您正在经历与 gprof 和其他基于相同概念的分析器常见的问题 - 1)对程序计数器进行采样以获取某种直方图,2)对函数进行仪器化以测量时间、计数并获取调用图。

实际上定位性能问题时,它们没有抓住重点。
关键不在于测量例程,而在于找到有问题的代码。

假设您有一个随机在墙钟时间对程序进行闪光灯式 X 光扫描的采样器。在每个样本中,程序可能处于 I/O 中间,可能处于您编译的代码中,也可能处于像 malloc 这样的某个库例程中。

但无论它在哪里,它花费那段时间的责任由调用堆栈上的每行代码共同承担,因为如果这些调用中的任何一个未被执行,它就不会在执行该调用请求的工作过程中。

所以查看在调用栈的多个示例中出现的每行代码(出现次数越多,越好)。那就是钱所在。不要只看程序计数器所在位置。在栈的较高位置有“深口袋”。


1

你尝试过这个问题中提到的其他工具吗?很有趣看看它们之间的比较。


0

是的,那些“秒”值并不是每次调用的时间。百分比时间是针对整个程序运行的。实际上,由于调用次数和每次调用所需的时间,你的程序在该函数中花费了31%的时间。

你可能想要阅读一下如何分析gprof的平面轮廓。

更正:抱歉,正如OP指出的那样,前两个秒值是累计值。

我认为你看到“自身”和“总共每次调用”的值为0有点奇怪。

引用gprof准确性部分的内容:“实际误差通常超过一个采样周期。事实上,如果一个值是采样周期的n倍,则其预期误差为n个采样周期的平方根。如果采样周期为0.01秒,foo的运行时间为1秒,则foo的运行时间的预期误差为0.1秒。从一个分析运行到下一个分析运行,它可能平均变化这么多。(有时会变化更多。)”
此外,可能相关的是,值得注意的是gprof不会对多线程程序进行分析。在这种情况下,最好使用SysprofOProfile

但这不可能:如果它被调用了5498021次,那么它应该需要0.32秒 * 5498021约等于20天的时间!此外,链接不清楚(我之前已经读过)-"This is the number of seconds accounted for by this function alone"似乎表示总共而不是每个调用的时间,但并不清楚。 - Jesse Beder

网页内容由stack overflow 提供, 点击上面的
可以查看英文原文,
原文链接