我的 python 脚本花时间在哪里？我的 cprofile / pstats 跟踪中是不是存在“丢失时间”？
Posted
技术标签:
【中文标题】我的 python 脚本花时间在哪里？我的 cprofile / pstats 跟踪中是不是存在“丢失时间”？【英文标题】：Where is my python script spending time? Is there "missing time" in my cprofile / pstats trace?我的 python 脚本花时间在哪里？我的 cprofile / pstats 跟踪中是否存在“丢失时间”？ 【发布时间】：2010-05-06 10:22:29 【问题描述】：我正在尝试分析一个长时间运行的 python 脚本。该脚本使用gdal module 对栅格GIS 数据集进行一些空间分析。该脚本当前使用三个文件，主脚本循环光栅像素find_pixel_pairs.py，lrucache.py 中的简单缓存和utils.py 中的一些杂项类。我已经在一个中等大小的数据集上分析了代码。 pstats 返回：
p.sort_stats('cumulative').print_stats(20)
Thu May 6 19:16:50 2010 phes.profile
355483738 function calls in 11644.421 CPU seconds
Ordered by: cumulative time
List reduced from 86 to 20 due to restriction <20>
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.008 0.008 11644.421 11644.421 <string>:1(<module>)
1 11064.926 11064.926 11644.413 11644.413 find_pixel_pairs.py:49(phes)
340135349 544.143 0.000 572.481 0.000 utils.py:173(extent_iterator)
8831020 18.492 0.000 18.492 0.000 range
231922 3.414 0.000 8.128 0.000 utils.py:152(get_block_in_bands)
142739 1.303 0.000 4.173 0.000 utils.py:97(search_extent_rect)
745181 1.936 0.000 2.500 0.000 find_pixel_pairs.py:40(is_no_data)
285478 1.801 0.000 2.271 0.000 utils.py:98(intify)
231922 1.198 0.000 2.013 0.000 utils.py:116(block_to_pixel_extent)
695766 1.990 0.000 1.990 0.000 lrucache.py:42(get)
1213166 1.265 0.000 1.265 0.000 min
1031737 1.034 0.000 1.034 0.000 isinstance
142740 0.563 0.000 0.909 0.000 utils.py:122(find_block_extent)
463844 0.611 0.000 0.611 0.000 utils.py:112(block_to_pixel_coord)
745274 0.565 0.000 0.565 0.000 method 'append' of 'list' objects
285478 0.346 0.000 0.346 0.000 max
285480 0.346 0.000 0.346 0.000 utils.py:109(pixel_coord_to_block_coord)
324 0.002 0.000 0.188 0.001 utils.py:27(__init__)
324 0.016 0.000 0.186 0.001 gdal.py:848(ReadAsArray)
1 0.000 0.000 0.160 0.160 utils.py:50(__init__)
前两个调用包含主循环 - 整个分析。剩余的调用总和不到 11644 秒中的 625 个。剩下的 11,000 秒用在了哪里？这一切都在find_pixel_pairs.py 的主循环中吗？如果是这样，我能否找出哪些代码行占用了大部分时间？
【问题讨论】：
phes() 是整个分析的包装函数 【参考方案1】：你说得对，大部分时间都花在了find_pixel_pairs.py 第 49 行的 phes 函数上。要了解更多信息，您需要将phes 分解为更多子功能，然后重新配置。
【讨论】：
是否可以返回tot time列的总和？
@Chuck：p.total_tt 属性中存储的tot time 列的总和，其中p 是p = pstats.Stats('script.prof') 返回的Stats 的实例。这也是打印在（上面）行上的值，“355483738 function calls in 11644.421 CPU seconds”（我的重点）。
OP 的tot time 列（上图）中的值加起来不完全等于 11644.421 的原因是print_stats(20) 只打印了top 20 most significant lines。
我通过reading pstats.py source code 找到了p.total_tt。它没有记录在here，所以要注意它不能完全保证是 API 的一部分......【参考方案2】：
忘记函数和测量。 Use this technique. 在调试模式下运行它，然后按 ctrl-C 几次。调用堆栈会准确地向您显示哪些代码行对时间负责。
新增：例如暂停10次。如果正如 EOL 所说，11000 秒中有 10400 秒直接花在 phes 上，那么在其中大约 9 次暂停时，它将停止就在那里。
另一方面，如果它在从phes 调用的某个子例程中花费了大部分时间，那么您不仅会看到它在该子例程中的位置，还会看到调用它的行，它们也是负责调用堆栈的时间等。
Don't measure. Capture.
【讨论】：
【参考方案3】：每个函数或方法的代码执行所花费的时间在tottime 列中。 cumtime 方法是tottime+花费在函数调用上的时间。
在您的列表中，您会看到您正在寻找的 11,000 秒直接由 phes 函数本身花费。它的调用只需要大约 600 秒。
因此，您希望按照 ~unutbu 的建议，通过将其分解为子功能并重新配置来找到 phes 中需要时间的内容。
【讨论】：
【参考方案4】：如果您已确定 find_pixel_pairs.py 中的 phes 函数/方法可能存在瓶颈，则可以使用 line_profiler 获取像这样的逐行执行配置文件性能数字（复制自另一个问题 @987654321 @):
Timer unit: 1e-06 s
Total time: 9e-06 s
File: <ipython-input-4-dae73707787c>
Function: do_other_stuff at line 4
Line # Hits Time Per Hit % Time Line Contents
==============================================================
4 def do_other_stuff(numbers):
5 1 9 9.0 100.0 s = sum(numbers)
Total time: 0.000694 s
File: <ipython-input-4-dae73707787c>
Function: do_stuff at line 7
Line # Hits Time Per Hit % Time Line Contents
==============================================================
7 def do_stuff(numbers):
8 1 12 12.0 1.7 do_other_stuff(numbers)
9 1 208 208.0 30.0 l = [numbers[i]/43 for i in range(len(numbers))]
10 1 474 474.0 68.3 m = ['hello'+str(numbers[i]) for i in range(len(numbers))]
有了这些信息，您确实不需要将phes 分解为多个子函数，因为您可以准确地看到哪些行的执行时间最长。
由于您提到您的脚本运行时间很长，我建议在尽可能有限的方法上使用line_profiler，因为虽然分析会增加额外的开销，但行分析会增加更多。
【讨论】：
以上是关于我的 python 脚本花时间在哪里？我的 cprofile / pstats 跟踪中是不是存在“丢失时间”？的主要内容，如果未能解决你的问题，请参考以下文章