我的Python脚本耗时在哪？cprofile/pstats跟踪中有没有“缺失时间”？

Question

我正在尝试分析一个运行时间很长的Python脚本。这个脚本使用gdal模块对栅格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__)

前两个调用包含了主要的循环，也就是整个分析过程。剩下的调用加起来不到625秒，而总共的运行时间是11644秒。那么剩下的11000秒都花在哪里了呢？这些时间都是在find_pixel_pairs.py的主循环中吗？如果是这样，我能找到哪些代码行耗时最多吗？

Answer 1

每个函数或方法执行代码所花的时间在 tottime 这一列里显示。cumtime 列则是 tottime 加上调用其他函数所花的时间。

在你的列表中，你看到你关注的那 11,000 秒是 phes 函数自己直接花的时间。而它调用的其他函数只花了大约 600 秒。

所以，你想要找出 phes 中哪些部分耗时，可以把它拆分成小函数，然后重新分析一下，就像 ~unutbu 建议的那样。

Answer 2

别管什么函数和测量了。用这个方法就行。只要在调试模式下运行，然后按几次ctrl-C。调用栈会告诉你到底哪些代码行在耗费时间。

补充一下：比如说，暂停10次。如果像EOL说的那样，11000秒中有10400秒都是在phes里花的，那么在大约9次暂停时，它会正好停在那里。如果它在某个从phes调用的子程序里花了很多时间，那么你不仅能看到它在那个子程序里的位置，还能看到调用它的代码行，这些也在耗费时间，依此类推，往上追溯调用栈。

别测量，捕捉。

Answer 3

你说得对，绝大部分时间都花在了find_pixel_pairs.py文件第49行的phes函数里。要想了解更多情况，你需要把phes函数拆分成更多的小函数，然后再进行性能分析。