简单的Python代码运行时间异常长，Hotshot报告不准确

Question

我正在尝试用hotshot来优化一些代码，原本以为它会很好用，因为它是一个高性能的性能分析工具。但不知为什么，我得到的结果却非常不准确。在我最近一次的性能分析中，hotshot报告我调用的顶层函数的总时间是7.946秒。但我根本不需要计时就知道它花的时间远远超过这个。自己用time.time()计时后发现，运行时间是42.465秒。我猜这可能是因为hotshot没有计算系统输入输出的时间，而我的程序正在批量处理很多二进制文件。

不过，通过使用更多的time.time()代码块，我把大部分额外的时间（hotshot没有注意到的）缩小到了一个较低级的处理函数上，这个函数没有进行任何输入输出操作。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万次，所以我也许不应该对花这么多时间感到惊讶。但这里显然没有进行任何输入输出操作。为什么hotshot会如此低估这个函数（以及整个程序）所花的时间呢？

在你问之前，我要说明的是，我没有使用多线程或其他类似的东西。

Answer 1

如果你在使用 Python 2.5 及以上版本，建议你换用 cProfile。因为 hotshot 这个工具似乎已经不再被支持了。

Answer 2

你想知道时间都花在哪里了，对吧？ 别把它当成是在测量时间。 想象一下，这是在找出哪些代码在运行时占用了大部分时间，不管总时间是多少。 这里有个例子。

很多性能分析工具都会陷入gprof的误区，比如忽略了被阻塞的时间，认为代码行数不重要，认为“自我时间”很重要，还认为测量一定要准确。