Optimizing Your Code

Faced with an under-performing program, you first need to determine which parts of the program are causing the issues. In order to do that, you'll need to "profile" your program, that is, to find out how much time is being spent in each part of the program. This will allow you to see which pieces are taking up the most CPU time. These pieces will then be the primary targets for optimization. The Python language includes a profile module that enables you to gather detailed information about how much time is being spent in different parts of your program.

You can determine which pieces of code run faster using the facilities of the timeit module. For our purposes, you'll be using just a few features of the library, but I encourage you to investigate the Python library documentation outside these lessons to learn more about it. Also, try writing your own simpler versions of library functions to learn more about different approaches to a given problem and how well they perform. Finally, don't forget that much opf the code in the standard library is Python. You can learn a lot by reading other people's code.

The cProfile module (written in C) functions just like the profile module, only faster. cProfile is not available in every computer's Python though. When that's the case, use the profile module instead. You can allow your program to make use of cProfile when it is available, and profile when it is not. A quick illustration will help you understand these tools. Here's how to import one of two modules with the same name:

try:
    import cProfile as profile
except ImportError:
    import profile

If cProfile is available, it is imported under the name profile. If it isn't available, the attempt to import it raises an ImportError exception, and the profile module is imported instead.

Create a new file named prfl.py as shown below:

def f1():
    for i in range(300):
        f2()

def f2():
    for i in range(300):
        f3()

def f3():
    for i in range(300):
        pass

import cProfile as profile
profile.run("f1()")

The profile.run() function takes as its argument, a string containing the code to be run, and then runs it with profiling active. If only one argument is given, the function produces output at the end of the run that summarizes the operation of the code.

Save and run it and you should see something like this:

         90304 function calls in 1.110 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    1.110    1.110 <string>:1(<module>)
        1    0.000    0.000    1.110    1.110 prfl2.py:1(f1)
      300    0.030    0.000    1.110    0.004 prfl2.py:5(f2)
    90000    1.080    0.000    1.080    0.000 prfl2.py:9(f3)
        1    0.000    0.000    1.110    1.110 {built-in method exec}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

A total of 90304 function calls are recorded during the execution of the code in a total of 1.110 seconds. The rest of the output is sorted by function name by default. The columns are:

By looking at the "tottime" column, we can see that the majority of the program's time is spent in the f3() function. In fact, if you could eliminate the time taken by the rest of the program altogether, the impact to the program's total execution time would be less than 5%. In other words, the f3() function is taking up 95% of the program's execution time. As Guido van Rossum says:

Rule number one: only optimize when there is a proven speed bottleneck. Only optimize the innermost loop. (This rule is independent of Python, but it doesn't hurt repeating it, since it can save a lot of work.) :-)

Sometimes you'll want more specific information from a profiling run. When that's the case, you'll use the second argument to profile.run—the name of a file to which your program will send the raw profiling data. Then you can process this data separately using the pstats module. In order to give the module enough data to work with, we'll use another artificially constructed program (there is no real computation taking place, but many function calls). Modify prfl.py to add more function calls:

def f1():
    for i in range(300):
        f2(); f3(); f5()

def f2():
    for i in range(300):
        f3()

def f3():
    for i in range(300):
        pass

def f4():
    for i in range(100):
        f5()

def f5():
    i = 0
    for j in range(100):
        i += j
    f6()

def f6():
    for i in range(100):
        f3()

import cProfile as profile
profile.run("f1()", "profiledata")

When you run this program, you won't see any output in the console window. The program creates a file named profiledata in the folder where prfl.py is located. Now you can work with that file using the pstats module, written precisely to allow analysis of the profile data.

The primary element in the pstats module is the Stats class. When you create an instance, you can give it the name(s) of one or more files as positional arguments. These files will have been created by profiling. You can also provide a stream keyword argument, which is an open file to which output will be sent (this defaults to standard output, meaning you see the output straight away).

Make sure to keep this window open after this interactive session:

>>> import pstats
>>> s = pstats.Stats("V:\\workspace\\Python4_Lesson05\\src\\profiledata")

>>> s.print_stats()
Mon Jun 25 17:55:43 2012    profiledata

         121204 function calls in 3.275 seconds

   Random listing order was used

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    3.275    3.275 {built-in method exec}
      300    0.770    0.003    2.458    0.008 prfl.py:5(f2)
      300    0.259    0.001    0.795    0.003 prfl.py:23(f6)
        1    0.007    0.007    3.275    3.275 prfl.py:1(f1)
        1    0.000    0.000    3.275    3.275 <string>:1(<module>)
   120300    2.229    0.000    2.229    0.000 prfl.py:9(f3)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
      300    0.010    0.000    0.804    0.003 prfl.py:17(f5)


<pstats.Stats object at 0x0000000002955198>
>>>

When you create a pstats.Stats instance, it loads the data, and you can manipulate it before producing output (you'll see how shortly). There are several refinements you can make to the output, by calling methods of your Stats instance.

>>> s.strip_dirs()   # shorten function references
<pstats.Stats object at 0x0000000002955198>
>>> s.print_stats()
Mon Jun 25 17:55:43 2012    profiledata

         121204 function calls in 3.275 seconds

   Random listing order was used

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    3.275    3.275 {built-in method exec}
        1    0.007    0.007    3.275    3.275 prfl.py:1(f1)
   120300    2.229    0.000    2.229    0.000 prfl.py:9(f3)
      300    0.259    0.001    0.795    0.003 prfl.py:23(f6)
      300    0.770    0.003    2.458    0.008 prfl.py:5(f2)
        1    0.000    0.000    3.275    3.275 <string>:1(<module>)
      300    0.010    0.000    0.804    0.003 prfl.py:17(f5)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}


<pstats.Stats object at 0x0000000002955198>
>>>

The strip_dirs() method has removed all of the directory information from the last column. strip_dirs() is applied to the default output; the path information isn't generally required. Next, you can sort the output to give you the most significant items first by providing one or more keys to the Stats.sort_stats() method. The keys that are acceptable currently are:

You may have noticed that 3 of the 8 lines of the output aren't particularly useful for our requirements. Fortunately, you can filter out the results you don't want by placing one or more restrictions on the output. Those restrictions can take one of three forms as additional arguments to print_stats():

• An integer will limit the output to the given number of lines.
• A floating-point number between 0 and 1 will restrict the output to the given proportion of entries.
• A regular expression will limit the output to those entries whose filename:lineno(function) fields contain the given regular expression.

You can limit the output to omit the details of the "structural" entries (those that relate strictly to the profiling framework) using the simple expression r"\.py", or, once the entries are sorted in the right order, by using the integer 5 in this case.

The restrictions are applied in order, so print_stats(0.1, "test") reports those lines out of the top tenth that match "test", whereas print_stats("test", 0.1) reports a tenth of all those lines matching "test." So, if there were a hundred lines in the source data, print_stats(0.1, "test") would print any lines that contain "test" from the first ten. print_stats("test", 0.1) would print one tenth of ALL the lines that contain "test." If every third line contained "test", print_stats(0.1, "test") would retrieve lines 3,6, and 9. print_stats("test", 0.1) would retrieve lines 3,6,9, and 11 -- four lines (assuming there were about 40 containing "test").

>>> s.sort_stats('calls', 'time')
<pstats.Stats object at 0x10057c510>
>>> s.print_stats(r"\.py")
Mon Jun 25 17:55:43 2012    profiledata

         121204 function calls in 3.275 seconds

   Ordered by: call count, internal time
   List reduced from 8 to 5 due to restriction <'\\.py'>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
   120300    2.229    0.000    2.229    0.000 prfl.py:9(f3)
      300    0.770    0.003    2.458    0.008 prfl.py:5(f2)
      300    0.259    0.001    0.795    0.003 prfl.py:23(f6)
      300    0.010    0.000    0.804    0.003 prfl.py:17(f5)
        1    0.007    0.007    3.275    3.275 prfl.py:1(f1)


<pstats.Stats object at 0x0000000002955198>
>>> s.print_stats(5)
Mon Jun 25 17:55:43 2012    profiledata

         121204 function calls in 3.275 seconds

   Ordered by: call count, internal time
   List reduced from 8 to 5 due to restriction <5>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
   120300    2.229    0.000    2.229    0.000 prfl.py:9(f3)
      300    0.770    0.003    2.458    0.008 prfl.py:5(f2)
      300    0.259    0.001    0.795    0.003 prfl.py:23(f6)
      300    0.010    0.000    0.804    0.003 prfl.py:17(f5)
        1    0.007    0.007    3.275    3.275 prfl.py:1(f1)


<pstats.Stats object at 0x0000000002955198>
>>>

You'll also want to know which functions call which other functions. The pstats.Stats object has the print_callers() and print_callees() methods that show you the calling relationships between various functions:

>>> s.sort_stats('calls', 'time')
<pstats.Stats object at 0x0000000002955198>

>>> s.print_callers(r"\.py")
   Ordered by: call count, internal time
   List reduced from 8 to 5 due to restriction <'\\.py'>

Function        was called by...
                    ncalls  tottime  cumtime
prfl.py:9(f3)   <-     300    0.005    0.005  prfl.py:1(f1)
                     90000    1.688    1.688  prfl.py:5(f2)
                     30000    0.536    0.536  prfl.py:23(f6)
prfl.py:5(f2)   <-     300    0.770    2.458  prfl.py:1(f1)
prfl.py:23(f6)  <-     300    0.259    0.795  prfl.py:17(f5)
prfl.py:17(f5)  <-     300    0.010    0.804  prfl.py:1(f1)
prfl.py:1(f1)   <-       1    0.007    3.275  <string>:1(<module>)


<pstats.Stats object at 0x0000000002955198>
>>> s.print_callees(r"\.py")
   Ordered by: call count, internal time
   List reduced from 8 to 5 due to restriction <'\\.py'>

Function         called...
                     ncalls  tottime  cumtime
prfl2.py:9(f3)   ->
prfl2.py:5(f2)   ->   90000    1.080    1.080  prfl2.py:9(f3)
prfl2.py:23(f6)  ->   30000    0.355    0.355  prfl2.py:9(f3)
prfl2.py:17(f5)  ->     300    0.010    0.365  prfl2.py:23(f6)
prfl2.py:1(f1)   ->     300    0.027    1.107  prfl2.py:5(f2)
                        300    0.004    0.004  prfl2.py:9(f3)
                        300    0.004    0.369  prfl2.py:17(f5)


<pstats.Stats object at 0x0000000002955198>
>>>

Being aware of which function calls which other functions can be useful when you are trying to locate specific calls that take more time than others.

Sometimes you write code and put a computation inside of the loop when it doesn't need to be. Under those circumstances there are gains to be made by moving the computation out of the loop, a technique usually referred to as "loop hoisting." Here is an example of loop hoisting:

>>> def loop1():
...     lst = range(10)
...     for i in lst:
...         x = float(i)/len(lst)
...
>>> def loop2():
...     lst = range(10)
...     ln = len(lst)
...     for i in lst:
...         x = float(i)/ln
...
>>> timeit("loop1()", "from __main__ import loop1")
7.349833011627197
>>> timeit("loop2()", "from __main__ import loop2")
4.197483062744141
>>>

What seems like a small change to the code makes a substantial difference!

Actually, the best way to optimize a loop is to remove it altogether. Sometimes you can do that using Python's built-in functions. Let's time four different ways to build the upper-case version of a list:

>>> oldlist = "the quick brown fox jumps over the lazy dog".split()
>>> def lf1(lst):
...     newlist = []
...     for w in lst:
...         newlist.append(w.upper())
...     return newlist
...
>>> def lf2(lst):
...     return [w.upper() for w in lst]
...
>>> def lf3(lst):
...     return list(w.upper() for w in lst)
...
>>> def lf4(lst):
...     return map(str.upper, lst)
...
>>>
>>> timeit("lf1(oldlist)", "from __main__ import lf1, oldlist")
4.409790992736816
>>> timeit("lf2(oldlist)", "from __main__ import lf2, oldlist")
3.492004156112671
>>> timeit("lf3(oldlist)", "from __main__ import lf3, oldlist")
4.758850812911987
>>> timeit("lf4(oldlist)", "from __main__ import lf4, oldlist")
0.5220911502838135
>>>

You haven't run into the map() built-in before, but it has some good things going for it. Its first argument is a function (in this case, the unbound upper() method of the built-in str type), and any remaining arguments are iterables. There are as many iterables as the function takes arguments, and the result is a list containing the return values of the function when called with corresponding elements of each iterable (if the iterables are not all the same length, map stops as soon as the first one is exhausted).

So, why is the map()-based solution so much faster? There are two reasons. First, it is the only solution that does not need to look up the upper() method in the str type each time around the loop. Second, the looping is done inside map(), which is written in the C language, which saves a lot of time.

Another way to remove a loop is to write the loop contents out as literal code. This is really only practical for short loops with a known number of iterations, but it can be a very effective technique, as the next example of "inlining loop code" shows:

>>> def f1():
...     pass
...
>>> def loopfunc():
...     for i in range(8):
...         f1()
...
>>> def inline():
...     f1(); f1(); f1(); f1(); f1(); f1(); f1(); f1()
...
>>> timeit("loopfunc()", "from __main__ import loopfunc")
1.9027259349822998
>>> timeit("inline()", "from __main__ import inline")
1.2639250755310059
>>>

There can be a substantial amount of overhead in looping. When function calls are written out explicitly, the execution time is 30% faster—a worthwhile gain. Of course, in this example the loop overhead does tend to dominate because there is so little actual computation happening.

Due to Python's dynamic nature, when the interpreter comes across an expression like a.b.c, it looks up a (trying first the local namespace, then the global namespace, and finally the built-in namespace), then it looks in that object's namespace to resolve the name b, and finally it looks in that object's namespace to resolve the name c. These lookups are reasonably fast; for local variables, lookups are extremely fast, since the interpreter knows which variables are local and can assign them a known position in memory. There are definitely gains to be had by storing references in local variables. Let's try removing Attribute Resolution from loops:

>>> class Small:
...    class Smaller:
...       x = 20
...    smaller = Smaller
...
>>> small = Small()
>>>
>>> def attr1():
...     ttl = 0
...     for i in range(50):
...         ttl += small.smaller.x
...     return ttl
...
>>> def attr2():
...     ttl = 0
...     x = small.smaller.x
...     for i in range(50):
...         ttl += x
...     return ttl
...
>>> timeit("attr1()", "from __main__ import small, attr1")
11.901235103607178
>>> timeit("attr2()", "from __main__ import small, attr2")
6.448068141937256
>>>

Here, the function doesn't actually execute a huge amount of computation, but we gain a lot in speed.

As we mentioned before, the interpreter knows which names inside your functions are local and it assigns them specific (known) locations inside the function call's memory. This makes references to locals much faster than to globals and (most especially) to built-ins. Let's test name reference speed from various spaces:

>>> glen = len # provides a global reference to a built-in
>>>
>>> def flocal():
...     name = len
...     for i in range(25):
...         x = name
...
>>> def fglobal():
...     for i in range(25):
...         x = glen
...
>>> def fbuiltin():
...     for i in range(25): 
...         x = len
...
>>> timeit("flocal()", "from __main__ import flocal")
1.743438959121704
>>> timeit("fglobal()", "from __main__ import fglobal")
2.192162036895752
>>> timeit("fbuiltin()", "from __main__ import fbuiltin")
2.259413003921509
>>>

This difference in speed isn't huge here, but it definitely shows that accessing a local variable is faster than accessing a global or a built-in. If many globals or built-ins are used inside a function, it makes sense to store a local reference to them. By contrast, if they are used only once, then you'd only be adding overhead to your function!

Don't consider performance while you're writing the code (although it's difficult for even experienced programmers to ignore). The primary goal of the initial programming process is a correct, functioning algorithm that is relatively easy to understand. Only after your tests demonstrate correct operation should you address performance.

Our intuition is not always the best gauge of what will run fast. You're much better off using timings to determine how well your program is running.

If you make two changes to a program, and the first makes a 10% improvement, that's great, right? But if the second takes performance down by 25%, the overall result will be worse than those of the unchanged program. Make your changes individually and methodically.

Guido van Rossum has yet more wisdom to share with us (I am a fan). In the article we mentioned above he presents us with a problem: given a list of integers in the range 0-127 (these are ASCII values; Python 2 was current when Guido wrote this), how does one create a string in which the characters have the ordinal values held in the corresponding positions in the list of integers? Guido (I think we have spent enough quality time with Guido to be on a first name basis now) realized that the fastest way to create such a string was to take advantage of the array module's ability to create one-byte integers; he came up with this code:

When you are writing code, the obvious way is the best. To extract maximum performance the best way is not always obvious! Did I really say this was a short lesson? Time flies when we're deep into the Python! You're doing really well so far.