我在一个文件中有一个 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 行只不过是文件头 block 注释的结束 """工作集中在第 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？
最佳答案
正如我在评论中提到的，当您无法让 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(strip)
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 开发版本得到了相同的结果——在内部使用时结果正确，在外部使用时所有费用都计入第一行代码。但是 PyPy 2.2/2.7.3 和 PyPy3 2.1b1/3.2.3 似乎都用 -m cProfile 给了我正确的结果。这可能只是意味着 PyPy 的 cProfile 是在 profile 之上伪造的，因为纯 Python 代码足够快。
无论如何，如果有人能弄清楚/解释为什么 -m cProfile 不起作用，那就太好了……但否则，这通常是一个非常好的解决方法。
关于Python 从 cProfile 获得有意义的结果，我们在Stack Overflow上找到一个类似的问题： https://stackoverflow.com/questions/21274898/