Hotshot 错误报告的简单 Python 代码运行时间异常长答案

【问题标题】：Simple Python code taking strangely long to run, incorrectly reported by HotshotHotshot 错误报告的简单 Python 代码运行时间异常长
【发布时间】：2011-10-01 14:52:13
【问题描述】：

我正在尝试使用 hotshot 优化一些代码，我希望它会很棒，因为它是高性能分析器和所有功能。但由于某种原因，我得到的结果非常不准确。在我最近的分析运行中，hotshot 报告我调用的顶级函数的累积时间为 7.946 秒。但即使没有时间，我也可以说它需要的时间比这要长得多。自己简单地使用 time.time() 为运行时间计时，运行时间为 42.465 秒。我猜这是因为 hotshot 不计算系统 IO 时间之类的，而我的程序正在批处理大量二进制文件？

但是，使用更多 time.time() 块，我将大部分额外时间使用（hotshot 没有注意到）缩小到不执行任何 IO 的较低级别的处理函数。 hotshot 报告此函数的总时间和累积时间分别为 4.414 和 6.185 秒。但是，再次使用 time.time() 语句，我发现它的累积时间超过了 30 秒。在一个相对简单的代码块上花费的累积时间为 7.32 秒，比 hotshot 所说的整个函数花费的时间要长。该块如下所示：

format = element[1]
if isinstance(format, tuple):
    format, operator, operand = format
else:
    operator, operand = (None, None)

就是这样。这个区块运行了超过 900 万次，所以我不应该对花这么多时间感到惊讶。但是这里显然没有进行 IO。为什么 hotshot 如此低估了这个函数（以及整个程序）所花费的时间？

在你问之前，不，我没有使用多线程或类似的东西。

【问题讨论】：

标签： python optimization profiling

【解决方案1】：

如果您使用的是 Python 2.5+，请尝试切换到 cProfile。 hotshot 似乎不再是 supported。

【讨论】：

出于兼容性原因，我实际上使用的是 Python 2.4。

【解决方案2】：

你想知道所有时间都去哪儿了，对吧？不要认为它是衡量时间。可以将其视为查找大部分时间都在堆栈上的代码行，而不管总数如何。 Here's an example.

许多分析器属于gprof traps，包括忽略阻塞时间、认为代码行无关紧要、认为“自我时间”很重要以及认为测量必须准确。

【讨论】：

我想我对 CPU 秒数和实时秒数之间的区别感到困惑。每个方法的分析时间与 hotshot 记录的总 CPU 运行时间相匹配，大约是方法运行实际时间的 1/4。我很困惑为什么函数运行的实际时间比 CPU 时间长得多；这似乎表明我的 CPU 花了很多时间在我的程序之外执行其他任务。但是我没有同时运行任何其他密集型程序，那为什么我的代码安排得如此稀疏呢？
@dpitch40：我不会浪费精力去试图弄清楚为什么任何分析器，更不用说能人，给出的总时间是没有意义的。原因是我的真正目标是使代码尽可能快，为此我想知道堆栈中的哪些语句占挂钟时间的很大一部分。究竟多高并不重要 - 找到陈述才是最重要的。（检查我给出的第一个链接。）我只知道一个“得到它”的分析器，那就是 Zoom。为了衡量整体的进步——别笑——我的手表还不错。