Python 从 cProfile 获得有意义的结果答案

【问题标题】：Python getting meaningful results from cProfilePython 从 cProfile 获得有意义的结果
【发布时间】：2014-02-12 00:53:08
【问题描述】：

我在一个文件中有一个 Python 脚本，它只需要 30 多秒即可运行。我正在尝试对其进行分析，因为我想大大减少这个时间。

我正在尝试使用 cProfile 分析脚本，但基本上它似乎告诉我的是，是的，主脚本需要很长时间才能运行，但并没有给出我期望的那种故障.在终端，我输入如下内容：

cat my_script_input.txt | python -m cProfile -s time my_script.py

我得到的结果是：

<my_script_output>
             683121 function calls (682169 primitive calls) in 32.133 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1   31.980   31.980   32.133   32.133 my_script.py:18(<module>)
   121089    0.050    0.000    0.050    0.000 {method 'split' of 'str' objects}
   121090    0.038    0.000    0.049    0.000 fileinput.py:243(next)
        2    0.027    0.014    0.036    0.018 {method 'sort' of 'list' objects}
   121089    0.009    0.000    0.009    0.000 {method 'strip' of 'str' objects}
   201534    0.009    0.000    0.009    0.000 {method 'append' of 'list' objects}
   100858    0.009    0.000    0.009    0.000 my_script.py:51(<lambda>)
      952    0.008    0.000    0.008    0.000 {method 'readlines' of 'file' objects}
 1904/952    0.003    0.000    0.011    0.000 fileinput.py:292(readline)
    14412    0.001    0.000    0.001    0.000 {method 'add' of 'set' objects}
      182    0.000    0.000    0.000    0.000 {method 'join' of 'str' objects}
        1    0.000    0.000    0.000    0.000 fileinput.py:80(<module>)
        1    0.000    0.000    0.000    0.000 fileinput.py:197(__init__)
        1    0.000    0.000    0.000    0.000 fileinput.py:266(nextfile)
        1    0.000    0.000    0.000    0.000 {isinstance}
        1    0.000    0.000    0.000    0.000 fileinput.py:91(input)
        1    0.000    0.000    0.000    0.000 fileinput.py:184(FileInput)
        1    0.000    0.000    0.000    0.000 fileinput.py:240(__iter__)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

这似乎没有告诉我任何有用的信息。绝大多数时间只是简单地列出为：

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1   31.980   31.980   32.133   32.133 my_script.py:18(<module>)

在my_script.py中，第18行无非是文件头块注释的结束"""，所以并不是说全部工作量都集中在第18行。整个脚本大部分是制作的主要是一些字符串拆分、排序和设置工作的基于行的处理，所以我期待找到大部分时间用于这些活动中的一项或多项。就目前而言，将 cProfile 结果中分组的所有时间都视为出现在注释行上没有任何意义，或者至少不能说明实际上一直在消耗什么。

编辑：我已经构建了一个与上述案例类似的最小工作示例来演示相同的行为：

mwe.py

import fileinput

for line in fileinput.input():
    for i in range(10):
        y = int(line.strip()) + int(line.strip())

然后调用它：

perl -e 'for(1..1000000){print "$_\n"}' | python -m cProfile -s time mwe.py

要得到结果：

         22002536 function calls (22001694 primitive calls) in 9.433 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    8.004    8.004    9.433    9.433 mwe.py:1(<module>)
 20000000    1.021    0.000    1.021    0.000 {method 'strip' of 'str' objects}
  1000001    0.270    0.000    0.301    0.000 fileinput.py:243(next)
  1000000    0.107    0.000    0.107    0.000 {range}
      842    0.024    0.000    0.024    0.000 {method 'readlines' of 'file' objects}
 1684/842    0.007    0.000    0.032    0.000 fileinput.py:292(readline)
        1    0.000    0.000    0.000    0.000 fileinput.py:80(<module>)
        1    0.000    0.000    0.000    0.000 fileinput.py:91(input)
        1    0.000    0.000    0.000    0.000 fileinput.py:197(__init__)
        1    0.000    0.000    0.000    0.000 fileinput.py:184(FileInput)
        1    0.000    0.000    0.000    0.000 fileinput.py:266(nextfile)
        1    0.000    0.000    0.000    0.000 {isinstance}
        1    0.000    0.000    0.000    0.000 fileinput.py:240(__iter__)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

我是否以某种方式错误地使用了 cProfile？

【问题讨论】：

你能告诉我们你的剧本吗？或者，更好的是stripped-down version that still exhibits the same odd profile behavior？
另外，您的my_script.pyc 是否可能已过期但不知何故其时间戳比my_script.py 晚？如果发生这种情况，您最终可能会从 .pyc 中实际运行（和分析）代码，但所有行号都已过期。
最后一件事，作为一个疯狂的猜测：你是在某处做一个f.readlines() 然后循环遍历结果吗？
最后一件事：有时，您无法让 cProfile 在外部工作，但您可以在内部使用它，例如，如this example 所示。
@abarnert 我在问题中添加了一个最小示例。

标签： python cprofile

【解决方案1】：

正如我在评论中提到的，当您无法让cProfile 在外部工作时，您通常可以在内部使用它。没那么难。

例如，当我在我的 Python 2.7 中使用 -m cProfile 运行时，我得到的结果实际上与你所做的相同。但是当我手动检测您的示例程序时：

import fileinput
import cProfile

pr = cProfile.Profile()
pr.enable()
for line in fileinput.input():
    for i in range(10):
        y = int(line.strip()) + int(line.strip())
pr.disable()
pr.print_stats(sort='time')

...这是我得到的：

         22002533 function calls (22001691 primitive calls) in 3.352 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
 20000000    2.326    0.000    2.326    0.000 {method 'strip' of 'str' objects}
  1000001    0.646    0.000    0.700    0.000 fileinput.py:243(next)
  1000000    0.325    0.000    0.325    0.000 {range}
      842    0.042    0.000    0.042    0.000 {method 'readlines' of 'file' objects}
 1684/842    0.013    0.000    0.055    0.000 fileinput.py:292(readline)
        1    0.000    0.000    0.000    0.000 fileinput.py:197(__init__)
        1    0.000    0.000    0.000    0.000 fileinput.py:91(input)
        1    0.000    0.000    0.000    0.000 {isinstance}
        1    0.000    0.000    0.000    0.000 fileinput.py:266(nextfile)
        1    0.000    0.000    0.000    0.000 fileinput.py:240(__iter__)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

这更有用：它告诉您可能已经预料到的情况，即您一半以上的时间都花在了调用 str.strip() 上。

另外，请注意，如果您无法编辑包含要分析的代码 (mwe.py) 的文件，您可以随时这样做：

import cProfile
pr = cProfile.Profile()
pr.enable()
import mwe
pr.disable()
pr.print_stats(sort='time')

即使这并不总是有效。例如，如果您的程序调用exit()，则必须使用try:/finally: 包装器和/或atexit。它调用os._exit()，或segfaults，你可能完全被水洗了。但这并不常见。

但是，我后来发现：如果将所有代码移出全局范围，-m cProfile 似乎可以工作，至少在这种情况下是这样。例如：

import fileinput

def f():
    for line in fileinput.input():
        for i in range(10):
            y = int(line.strip()) + int(line.strip())
f()

现在-m cProfile 的输出包括：

2000000 4.819 0.000 4.819 0.000 :0（条带） 100001 0.288 0.000 0.295 0.000 文件输入.py:243(下一个)

我不知道为什么这也让它慢了一倍……或者这只是缓存效应；距离我上次运行它已经有几分钟了，我在这之间做了很多网页浏览。但这并不重要，重要的是大部分时间都在合理的地方收费。

但是如果我改变它以将外部循环移动到全局级别，并且只有它的主体变成一个函数，大部分时间都会再次消失。

另一种选择，除非作为最后的手段，否则我不会建议......

我注意到，如果我使用 profile 而不是 cProfile，它在内部和外部都可以工作，从而为正确的调用计费。但是，这些调用也慢了大约 5 倍。并且似乎还有额外的 10 秒的持续开销（如果在内部使用，则会向 import profile 收费，如果在外部使用，则在第 1 行收取任何费用）。因此，要发现split 使用了我 70% 的时间，而不是等待 4 秒并执行 2.326 / 3.352，我必须等待 27 秒，然后执行 10.93 / (26.34 - 10.01)。没什么好玩的……

最后一件事：我使用 CPython 3.4 开发版本得到了相同的结果——在内部使用时结果正确，在外部使用时所有费用都计入第一行代码。但是 PyPy 2.2/2.7.3 和 PyPy3 2.1b1/3.2.3 似乎都给了我正确的结果-m cProfile。这可能只是意味着 PyPy 的 cProfile 是在 profile 之上伪造的，因为纯 Python 代码足够快。

无论如何，如果有人能弄清楚/解释为什么 -m cProfile 不起作用，那就太好了……但否则，这通常是一个非常好的解决方法。

【讨论】：

并不是-m cProfile 不工作。我认为它考虑了加载解释器和导入所有需要的库所需的时间。这可能是脚本的第 1 行。
@arocks 在没有任何分析的情况下，我的脚本需要大约 30 秒才能执行。如果分析器在我的脚本的第 18 行报告的大约 30 秒确实用于设置，那么剩余的几分之一秒不会占其余的工作。在实时观看了我的真实脚本的输出后，我可以确认导入等在脚本到达实际工作部分并开始产生结果之前只需要很少的时间。
@arocks：不，您可以轻松验证所有这些都在几分之一秒内完成。例如，在内部for 循环的末尾添加一个break，然后再将另一个缩进。所有相同的工作都在做，完全一样。然后-m cProfile 它，它会告诉你还有 0.002 秒。此外，如果您在 3.4 而不是 2.7 中运行，则大多数启动和导入机制都是在 Python 中，并且可以正确充电，大约需要 0.001 秒。
@abarnert 谢谢 - 这个答案提供了很多有用的信息。可悲的是，在我的真实脚本中，如果我在脚本本身中添加分析，分析器报告整个脚本只需要 0.151 秒即可运行，尽管实际上它显然需要更长的时间（约 30 秒）。我想这完全是另一个问题。
@BryceThomas：我还发现了一件事；让我再编辑一次……虽然我怀疑它对你没有帮助，但它可能会。