0

I am using Python cProfile as described in the answer to this question to optimize my code. I found out that a call to a particular method inside a function, which is made many times per second, takes more time than I expected. The structure of my code can be summed up like this:

while(IShouldBeRunning):
    d = object.intersection(args)

where object is an instance of a class and intersection is a method of that class, which is located in a separate file geometries.py. I measured the time required to call this method once in two different ways. First, I measured the time inside the while loop shown above:

while(IShouldBeRunning):
    pr = cProfile.Profile()
    pr.enable()

    d = object.intersection(args)

    pr.disable()
    break

Next, I measured it inside the intersection method:

def intersection(self, args):

    pr = cProfile.Profile()
    pr.enable()

    *some computation*

    pr.disable()

The respective outputs of pstats are shown below:

12 function calls in 0.006 seconds

Ordered by: cumulative time

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    1    0.005    0.005    0.006    0.006 geometries.py:11(intersection)
    1    0.000    0.000    0.001    0.001 fromnumeric.py:1631(sum)
    1    0.000    0.000    0.001    0.001 _methods.py:31(_sum)
    1    0.001    0.001    0.001    0.001 {method 'reduce' of 'numpy.ufunc' objects}
    2    0.000    0.000    0.000    0.000 {built-in method array}
    1    0.000    0.000    0.000    0.000 twodim_base.py:83(flipud)
    ...


11 function calls in 0.001 seconds

Ordered by: cumulative time

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    1    0.000    0.000    0.001    0.001 fromnumeric.py:1631(sum)
    1    0.000    0.000    0.001    0.001 _methods.py:31(_sum)
    1    0.001    0.001    0.001    0.001 {method 'reduce' of 'numpy.ufunc' objects}
    2    0.000    0.000    0.000    0.000 {built-in method array}
    1    0.000    0.000    0.000    0.000 twodim_base.py:83(flipud)
    ...

It seems that the code inside the intersection method does not take much time to run, but the call to this method takes much more time. Am I interpreting this correctly? If so, why is there such an overhead in the call to this method and is it possible to reduce it?

Community
  • 1
  • 1
Iodestar
  • 198
  • 2
  • 13
  • 1
    first of all i would move `pr = cProfile.Profile()` outside of your loop and i would completely remove it from `intersection()`. Why are you enabling/disabling profiling in loop and then additionally in `intersection()`? – MaxU - stand with Ukraine Mar 17 '16 at 14:14
  • Is there any reason you don't just profile the whole thing? Tottime vs cumtime is suppposed to tease out in function only vs in function + functions it calls. And it is hard to see whats going on wrt frequency if all you have is 1 call of 0.001. And esp avoid opeing profile within loop. – JL Peyret Mar 17 '16 at 14:15
  • @MaxU I profiled inside the loop for the first measurement only. Then, I removed it and profiled `intersection()`, so it was enabled only once for each run. – Iodestar Mar 17 '16 at 15:49
  • @JLPeyret I had to modify my code since all this is usually running inside a thread, and I read somewhere that profiling should be done on the main thread only. Would it help if I did something like: `for k in range(0,100): d = object.intersection(args)` and enable/disable the profiling before/after the loop? – Iodestar Mar 17 '16 at 15:53
  • Dunno. How about passing the **pr** reference to your thread? Or running wo threads for profiling? I do know you aint gonna get much insight from 1 per call profiling. Google profile python threads. See also http://stackoverflow.com/questions/653419/how-can-i-profile-a-multithread-program-in-python – JL Peyret Mar 17 '16 at 16:02

0 Answers0