Function call is taking 10 seconds

Question

I've profiled my code with cProfile to find bottlenecks and I've found a peculiar one.

My code is structured like so:

def A1Distance(a_list):
    #returns something

pr = cProfile.Profile()
pr.enable()
x = A1Distance(list_comprehension)
pr.disable()

cProfile has it run for a total of 17.554 seconds. The top function in terms of total time is:

ncalls  tottime  percall  cumtime  percall filename:lineno(function)

    1    9.884    9.884   17.554   17.554 Cov_Opt_Parallel.py:141(A1Distance)

as you can see, A1Distance takes about 10 seconds and is called once. If I put the pr.enable() and pr.disable() INSIDE the function, it's the same output but without the 10 seconds for A1Distance. Thus, it appears to be taking 10 seconds to merely call a function. Any suggestions for what could be the reason/fix for this?

Is the list comprehension you're feeding as an argument expensive to perform? It's produced outside the function, then passed in, so moving the profiling inside the function wouldn't account for the cost of constructing the `list`. — ShadowRanger, Oct 08 '15 at 00:55
A1Distance is not recursive. I previously had it do a thing 500 times, but when I reduced that to 100 the function call took only 3.114 seconds. The execution time of the list comprehension showed as 0.000 when I profiled it by itself. — user3259201, Oct 08 '15 at 01:09
I suspect you messed up when you moved the profiling inside the function. It's really unlikely that it takes 10 seconds to call a function. And the fact that changing the number of repetitions inside the function changed the timing implies that the cost is in the function, not the call. — Barmar, Oct 08 '15 at 01:14
I re-ran the profiling within the function (enable being the first thing, disable right before the return statement) and I am seeing the same thing. — user3259201, Oct 08 '15 at 01:27
break out the calculation of the list comprehension i.e. `a = ; A1(a)`, then you can time them separately. also, look into the line_profiler... — Corley Brigman, Oct 08 '15 at 02:31
As far as you've shown the code could be `def A1Distance(s): time.sleep(10); return s`. There is an utter lack of information about the phenomenon you want help with. — msw, Oct 08 '15 at 02:31

score 1 · Answer 1 · answered Oct 08 '15 at 02:22

It's your list_comprehension that's taking 10 seconds. The arguments to a function are evaluated before the function is called, so if you profile inside the function, the costly list_comprehension is already done.

See this for example:

import time, cProfile

def func_a(a_list):
    return len(a_list)

def func_b(a_list, pr):
    pr.enable()
    ret = len(a_list)
    pr.disable()
    return ret


def main():
    pr = cProfile.Profile()
    pr.enable()
    func_a([time.sleep(x) for x in range(3)])
    pr.disable()
    pr.print_stats()

    pr = cProfile.Profile()
    func_b([time.sleep(x) for x in range(3)], pr)
    pr.print_stats()

    pr = cProfile.Profile()
    pr.enable()
    [time.sleep(x) for x in range(3)]
    pr.disable()
    pr.print_stats()

if __name__ == '__main__':
    main()

Will output something like:

     7 function calls in 3.006 seconds

Ordered by: standard name

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    1    0.000    0.000    0.000    0.000 tmp.py:3(func_a)
    1    0.000    0.000    0.000    0.000 {len}
    1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
    1    0.000    0.000    0.000    0.000 {range}
    3    3.006    1.002    3.006    1.002 {time.sleep}


     2 function calls in 0.000 seconds

Ordered by: standard name

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    1    0.000    0.000    0.000    0.000 {len}
    1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}


     5 function calls in 3.004 seconds

Ordered by: standard name

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
    1    0.000    0.000    0.000    0.000 {range}
    3    3.004    1.001    3.004    1.001 {time.sleep}

Function call is taking 10 seconds

1 Answers1