# Python Performance Tuning

Having just built a solver for KenKen puzzles, this is a good opportunity to take a look at performance tuning in Python. Today we’ll look at some basic instrumentation, and begin searching for bottlenecks in the solver.

### Preliminaries

For the purposes of this post, I’m assuming that:

* The solver code is stored in a file named neknek_1.py
* The neknek_1.py file is on the import path
* A 9×9 test puzzle is stored in a file named 9×9.txt
* The 9×9.txt file is in the current working directory

Here is the 9×9 test puzzle I’ll be using for performance measurement:

``````#	9
*	240	A1 B1 A2
+	12	B2 A3 B3
!	9	A4
-	5	A5 A6
*	72	A7 B7
+	7	A8 B8 C8
/	2	A9 B9
*	56	C3 B4 C4
+	11	B5 B6
/	2	C1 C2
+	10	C5 C6 D6
*	42	C7 D7 D8
+	27	C9 D9 E9 F9 G9
/	2	D1 E1
+	19	D2 D3 D4
+	16	D5 E5 F5
!	3	E2
-	1	E3 E4
+	24	E6 E7 E8
*	252	F1 G1 G2 G3
+	6	F2 F3 F4
*	216	F6 G5 G6
+	15	F7 G7 F8
+	16	G4 H4 I4
*	90	G8 H8 I8
+	23	H1 I1 I2
+	15	H2 H3 I3
-	3	H5 H6
*	12	H7 I7
-	7	H9 I9
-	2	I5 I6``````

### Timeit

The simplest Python tuning tool is probably the `timeit` module. From PythonWin it would be invoked this way:

``````>>> import timeit
>>> timeit.Timer('neknek_1.solve(neknek_1.Puzzle("9x9.txt"))', 'import neknek_1').timeit(number=10)/10``````

This code will load and solve the 9×9 puzzle 10 times, and return the average time (as a float, in seconds) that a single load-and-solve loop took.

Timeit is a crude but effective way to see the impact of optimizations on a macro level. On my machine, at the moment, it returns an estimate of 0.45s per 9×9 puzzle. (Note that this is significantly lower than what I observed yesterday, indicating that some care must be used when evaluating the results of this module.)

### Hotshot

The `hotshot` module a true profiler; it will log individual function entry/exit information during program execution, writing the results to a file. The output file can be parsed by tools packaged with the `hotshot` module. From PythonWin, the `hotshot` profiler would be invoked this way:

``````>>> import hotshot
>>> import neknek_1
>>> prof = hotshot.Profile('hotshot_nn_stats')
>>> prof.run('neknek_1.solve(neknek_1.Puzzle("9x9.txt"))').close()``````

To view a summary of the profiler’s results, use these commands:

``````>>> import hotshot.stats

which will output:

``````         297518 function calls (36546 primitive calls) in 3111.408 CPU seconds

Ordered by: internal time

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
133583/11855 1221.719    0.009 2028.554    0.171 neknek_1.py:18()
115588/4363  923.962    0.008 2145.681    0.492 neknek_1.py:15(can_make_sum_p)
44  207.178    4.709 3086.981   70.159 neknek_1.py:112(constrain)
14470/1329  150.414    0.010  283.972    0.214 neknek_1.py:21(can_make_product_p)
18308/3559  133.558    0.007  247.684    0.070 neknek_1.py:24()
640  131.804    0.206 2760.608    4.313 neknek_1.py:44(apply)
1000  118.984    0.119  118.984    0.119 neknek_1.py:78(apply)
2450   59.254    0.024 2570.519    1.049 neknek_1.py:48()
2528   58.285    0.023   58.285    0.023 neknek_1.py:45()
4378   54.718    0.012 2200.400    0.503 neknek_1.py:56(_test_component)
1392   18.611    0.013  302.583    0.217 neknek_1.py:67(_test_component)
44/1    7.363    0.167 2112.332 2112.332 neknek_1.py:132(search)
1213    6.575    0.005    6.575    0.005 neknek_1.py:137()
910    5.532    0.006    5.532    0.006 neknek_1.py:63(_test_component)
66/2    2.864    0.043 2111.620 1055.810 neknek_1.py:139()
288    2.750    0.010    2.750    0.010 neknek_1.py:74(_test_component)
1    2.416    2.416 3109.565 3109.565 neknek_1.py:100(solve)
1    1.215    1.215    1.740    1.740 neknek_1.py:91(__init__)

... clipped ...``````

### Initial Observations

The first thing to notice is the absolutely stupendous amount of time devoted to `can_make_sum_p()` – nearly 2/3rds of the execution time is devoted to this single utility function. If you recall, it’s source code is:

``````# Can we select exactly one member from each set s.t. the sum of all selected members is t?
def can_make_sum_p(t, sets):
if (not sets): return (t == 0)
head = sets[0]; tail = sets[1:]
return any(can_make_sum_p(t-e, tail) for e in head if e <= t)``````

Let's see if we can speed this up a little.

### Base Case

The simplest thing to address is the base case. Right now, the base case of the recursive call is reached when `sets` is empty; at that point, the function returns `True` iff `t` equals 0. This is a bit silly; an (almost) equally good base case is reached when `sets` contains only one iterable; the function should return `True` iff `t` is a member of this iterable. The code:

``````# Can we select exactly one member from each set s.t. the sum of all selected members is t?
def can_make_sum_p(t, sets):
if (len(sets) == 1): return (t in sets[0])
head = sets[0]; tail = sets[1:]
return any(can_make_sum_p(t-e, tail) for e in head if e <= t)``````

With this single change, `timeit` now reports a per-loop time of 0.32s, and the `hotshot` profiler reports these results:

``````         94797 function calls (35465 primitive calls) in 1377.959 CPU seconds

Ordered by: internal time

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
21749/4177  282.142    0.013  456.155    0.109 neknek_1.py:15(can_make_sum_p)
44  179.129    4.071 1354.233   30.778 neknek_1.py:112(constrain)
24660/11003  174.013    0.007  340.939    0.031 neknek_1.py:18()
14592/1357  160.274    0.011  308.033    0.227 neknek_1.py:21(can_make_product_p)
18409/3670  147.759    0.008  271.829    0.074 neknek_1.py:24()
635  121.681    0.192 1072.522    1.689 neknek_1.py:44(apply)
1039  102.325    0.098  102.325    0.098 neknek_1.py:78(apply)
2424   57.304    0.024  897.517    0.370 neknek_1.py:48()
2489   53.324    0.021   53.324    0.021 neknek_1.py:45()
4192   49.542    0.012  505.696    0.121 neknek_1.py:56(_test_component)
1422   18.537    0.013  326.570    0.230 neknek_1.py:67(_test_component)
44/1    7.163    0.163 1072.548 1072.548 neknek_1.py:132(search)
1213    6.361    0.005    6.361    0.005 neknek_1.py:137()
947    5.310    0.006    5.310    0.006 neknek_1.py:63(_test_component)
256    2.637    0.010    2.637    0.010 neknek_1.py:74(_test_component)
66/2    2.626    0.040 1071.892  535.946 neknek_1.py:139()
1    2.513    2.513 1376.102 1376.102 neknek_1.py:100(solve)
1    1.228    1.228    1.761    1.761 neknek_1.py:91(__init__)

... clipped ...``````

As you can see, changing the base case results in an ~84% reduction in the calls to `can_make_sum_p()`, and an ~29% reduction in execution time.

### Coming Attractions

Tomorrow we'll explore further optimizations, using the same tools.

Share and Enjoy:
This entry was posted in Projects, Python. Bookmark the permalink.