Где мой скрипт на Питоне проводит время? Есть ли "пропущенное время" в моей трассировке cprofile / pstats? - PullRequest
Новая
       13

Где мой скрипт на Питоне проводит время? Есть ли "пропущенное время" в моей трассировке cprofile / pstats?

2 голосов
/ 06 мая 2010

Я пытаюсь профилировать долго работающий скрипт Python. Сценарий выполняет пространственный анализ набора растровых данных ГИС с использованием модуля gdal . В настоящее время сценарий использует три файла: основной сценарий, который перебирает растровые пиксели с именем find_pixel_pairs.py, простой кэш в lrucache.py и некоторые классы misc в 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 секунд. Где тратятся оставшиеся 11 000 секунд? Это все в главном цикле find_pixel_pairs.py? Если да, могу ли я узнать, какие строки кода занимают большую часть времени?

Ответы [ 4 ]

1 голос
/ 06 мая 2010

Забудьте функции и измерения. Используйте эту технику. Просто запустите ее в режиме отладки и несколько раз нажмите Ctrl-C. Стек вызовов покажет вам, какие именно строки кода отвечают за время.

Добавлено: например, сделать паузу в 10 раз. Если, как говорит EOL, 10400 секунд из 11000 тратятся непосредственно в phes, то примерно в 9 из этих пауз он остановится прямо там . Если, с другой стороны, он проводит большую часть времени в какой-то подпрограмме, вызываемой из phes, то вы не только увидите, где она находится в этой подпрограмме, но и увидите строки, которые ее вызывают, что ответственность за время и т. д. до стека вызовов.

Не измеряйте. Capture.

1 голос
/ 06 мая 2010

Вы правы, что большую часть времени тратит на функцию phes в строке 49 find_pixel_pairs.py. Чтобы узнать больше, вам нужно разбить phes на несколько подфункций, а затем перепрофилировать.

0 голосов
/ 06 сентября 2017

Если вы определили потенциальные узкие места в функции / методе phes в find_pixel_pairs.py, вы можете использовать line_profiler для получения таких показателей производительности построчного профиля выполнения (скопировано из другого вопроса здесь ): 

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 для максимально ограниченного числа методов, потому что, хотя профилирование добавляет дополнительные издержки, профилирование строки может добавить больше.

0 голосов
/ 06 мая 2010

Время, потраченное на выполнение кода каждой функции или метода, указано в столбце tottime. Метод cumtime - это tottime + время, потраченное на вызываемые функции.

В своем списке вы видите, что 11 000 секунд, которые вы ищете, тратятся непосредственно самой функцией phes. То, что он называет, занимает около 600 секунд.

Таким образом, вы хотите найти то, что занимает время в phes, разбив его на подфункции и перепрофилировав, как предложил ~ unutbu.

...