optimisation / python

Python Script Profiler

I have just discovered the profiler utility for Python – what a fantastic tool! By running any Python script with the cProfile utility, you get a profile of the running time and function calls within your program which will let you identify any bottlenecks or expensive operations.

To invoke the profiler at the command prompt:

~$ python -m cProfile my_script.py

To test this out, I made a simple script to sum the even numbers between 0 and 1000, using 3 separate functions: one interative, one recursive, and one using a generator:

# profile_test.py

def iterative(n):
    x, my_range = 0, []
    while x < n:
        x += 1
        if not x % 2:
            my_range += [x]
            print(my_range)
    return my_range

def recursive(n):
    if n <= 0:
        return n
    if not n % 2:
        return n + recursive(n - 1)

    return 0 + recursive(n - 1)

def generator(n):
    while n >= 0:
        if not n % 2:
            yield n
        n = n - 1

if __name__ == '__main__':
    print(sum(iterative(1000)))
    print(recursive(900))
    print(sum(generator(1000)))

and the results show:

~$ python -m cProfile profile_tester.py 
250500
202950
250500

1408 function calls (508 primitive calls) in 1.160 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    901/1    0.003    0.000    0.003    0.003 profile_tester.py:17(recursive)
      502    0.000    0.000    0.000    0.000 profile_tester.py:25(generator)
        1    0.001    0.001    1.160    1.160 profile_tester.py:6()
        1    1.155    1.155    1.155    1.155 profile_tester.py:8(iterative)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        2    0.000    0.000    0.001    0.000 {sum}

The 3 functions aren’t quite equivalent. For example, python’s max recursion depth won’t let the recursive function go all the way to 1000. But on the whole, we can get a fair idea of what is going on.

We can see just how expensive it is to print to the screen. The print() statement that I just arbitrarily threw into the iterative approach takes nearly ALL of the time to run! If I remove this, and increase the upper limit to 10,000,000 we can see the relative efficiency of the generator function over the iterative:

~$ python -m cProfile profile_tester.py 
25000005000000
202950
25000005000000
         5000908 function calls (5000008 primitive calls) in 4.436 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    901/1    0.001    0.000    0.001    0.001 profile_tester.py:17(recursive)
  5000002    1.516    0.000    1.516    0.000 profile_tester.py:25(generator)
        1    0.036    0.036    4.436    4.436 profile_tester.py:6()
        1    2.401    2.401    2.401    2.401 profile_tester.py:8(iterative)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        2    0.482    0.241    1.998    0.999 {sum}

I also think it is interesting, that 5,000,000 calls to the generator function is still faster than a single for loop. It would be good to know how expensive each function was in terms of memory as well.

I would also be interested in seeing the cost of the my_range.append(x) call, so I constructed a simple test to compare append() with a list comprehension:

n = 0
my_range = []
while n < 1000000:
    my_range.append(n)
    n += 1

n = 1000000
my_comprehension = [x for x in range(n)]

The results below confirm that a list comprehension is much quicker that appending to a list in Python 3000 (which is a good thing – because they keep telling us this :p)

~$ python -m cProfile profile_test2.py 
         1000003 function calls in 0.507 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.429    0.429    0.507    0.507 profile_test2.py:1()
  1000000    0.062    0.000    0.062    0.000 {method 'append' of 'list' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.017    0.017    0.017    0.017 {range}

All-in-all I think this is a really powerful utility, which will help me identify any bottlenecks or expensive operations in my scripts / algorithms.

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s