Where is my python script spending time? Is time missing in my cprofile / pstats trace?
I am trying to profile a long python script. The script does some spatial analysis on raster GIS data using the gdal module . The script currently uses three files, the main script that iterates over the bitmap pixels called find_pixel_pairs.py
, a simple cache in, lrucache.py
and some different classes in utils.py
. I have profiled the code on a moderate sized dataset. pstats
returns:
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__)
The top two calls contain the main loop - the entire analysis. The rest of the calls are less than 625 out of 11644 seconds. Where are the other 11,000 seconds? Is everything within the main loop find_pixel_pairs.py
? If so, can I find out which lines of code are taking the most time?
a source to share
Forget about functions and dimensions. Use this method. Just run it in debug mode and do ctrl-C a few times. The call stack will tell you which lines of code are timing.
Added: For example, pause it 10 times. If, according to EOL, 10,400 seconds out of 11,000 are consumed directly in phes
, then for about 9 of those pauses it will stop right there. If, on the other hand, it spends most of its time on some subroutine called from phes
, then you will not only see where it is in that subroutine, but you will see the lines that call it, as well as the person responsible for the time, etc. , up the call stack.
a source to share
The time taken to execute the code of each function or method is in a column tottime
. Method cumtime
tottime
+ time spent on called functions.
In your listing, you can see that the 11,000 seconds you're looking for are consumed directly by the function itself phes
. What he calls it only takes about 600 seconds.
So you want to find what is taking time in phes
by breaking it down into sub-functions and repurposing as ~ unutbu suggested.
a source to share
If you've identified the potential for bottlenecks in a function / method phes
in find_pixel_pairs.py
, you can use line_profiler
to get the same runtime profile performance metrics in one go (copied from another question here ):
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))]
With this information, you don't need to split phes
into multiple sub-functions because you can see exactly which lines have the longest execution time.
Since you note that your script takes a long time to run, I would recommend using line_profiler
as few methods as possible, since since profiling adds additional overhead, string profiling can add more.
a source to share