Python从cProfile获得有意义的结果

Question

我的文件中有一个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？

Answer 1

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

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

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
fileinput.py:243（下一个）

我不知道为什么这也会使速度慢两倍…也许这只是缓存效果；从我上次运行到现在已经过了几分钟，并且我之间进行了很多网络浏览。但这并不重要，重要的是大部分时间都在合理的地方进行充电。

但是，如果我更改此设置以将外循环移动到全局级别，并且仅将其主体移动到函数中，则大多数时候又会消失。

另一种选择，除非万不得已，否则我不会建议…

我注意到，如果我使用配置文件而不是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。这可能仅仅意味着PyPycProfile被伪造了，profile因为纯Python代码足够快。

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