Python从cProfi获得有意义的结果

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在外部工作时，您通常可以在内部使用它。没那么难。

例如，当我在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 fileinput.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.4dev时，我得到了相同的结果构建正确的结果，当在外部使用时，所有的东西都记在第一行代码中。但是PyPy 2.2/2.7.3和pypy32.1b1/3.2.3似乎都给出了正确的结果。这可能只是意味着PyPy的cProfile是在profile之上伪造的，因为纯Python代码足够快。

---

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