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:wrapper和/或atexit.它可以称之为os._exit()或段错误,你可能完全被冲洗了.但这并不常见.

但是,后来我发现了一些事情:如果将所有代码移出全局范围,-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(next)

我不知道为什么这也让它慢了两倍......或者这只是一个缓存效果; 自从我上次运行它以来已经过了几分钟,我之间已经进行了大量的网页浏览.但这并不重要,重要的是大部分时间都是在合理的地方收费.

但是如果我改变它以将外循环移动到全局级别,并且仅将其主体转换为函数,则大多数时间会再次消失.

另一种选择,我不建议除非作为最后的手段......

我注意到如果我使用profile而不是cProfile,它可以在内部和外部工作,为正确的调用充电.但是,这些调用也慢了约5倍.并且似乎还有额外的10秒恒定开销(import profile如果在内部使用则会被充电,如果在外部使用,则在第1行上进行充电).所以,要发现这split是我70%的时间,而不是等待4秒并且做2.326/3.352,我必须等待27秒,然后做10.93 /(26.34 - 10.01).没什么好玩的......

最后一件事:我在内部使用CPython 3.4 dev build-correct结果得到相同的结果,在外部使用时,所有内容都被收取到第一行代码.但PyPy 2.2/2.7.3和PyPy3 2.1b1/3.2.3似乎都给我正确的结果-m cProfile.这可能仅仅意味着PyPy cProfile是伪造的,profile因为纯Python代码足够快.

无论如何,如果有人能够弄清楚/解释为什么-m cProfile不起作用,那就太好了......但除此之外,这通常是一个非常好的解决方法.