Profiling Python Code
For the first time in 9 years, this vacation break I have done absolutely nothing. Wow what a coach potato I have become! Well that is not totally true, just for fun I started going over Python and, as usual, for any new language I end writing a simple genetic algorithm. I like the flexibility and compactness of the code (no verbose at all). However when I fire my first run (yes, the good old OneMax problem), I realized that some of my assumptions about coding did not directly transfer. Yes, it was a bit slow. So I started digging for a profiler and, surprise!, it comes with the Python interpreter. Here is an example on how to run the profiling capabilities
import cProfile cProfile.run('main()')
The cProfile module is a profile based coded in C. If you do not have it in your install you could run the same code with the profile module instead (highly likely to be in your install). Also if you are using Python < 2.5 you may also want to use the profile instead (I read somewhere there was a bug on the cProfile, but I could not recall where I saw it). Below you can read the output of the profiler.
1246109 function calls (1096109 primitive calls) in 1.428 CPU seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 1.428 1.428 :1()
156000/6000 0.366 0.000 0.905 0.000 copy.py:144(deepcopy)
29953 0.008 0.000 0.008 0.000 copy.py:197(_deepcopy_atomic)
6000 0.154 0.000 0.535 0.000 copy.py:223(_deepcopy_list)
6000 0.034 0.000 0.740 0.000 copy.py:250(_deepcopy_dict)
47953 0.105 0.000 0.131 0.000 copy.py:260(_keep_alive)
6000 0.040 0.000 0.861 0.000 copy.py:276(_deepcopy_inst)
3000 0.180 0.000 0.258 0.000 crossovers.py:6(uniformCrossover)
6600 0.005 0.000 0.017 0.000 fitnesses.py:5(oneMax)
6000 0.006 0.000 0.006 0.000 ind_n_pop_classes.py:16(__init__)
11 0.023 0.002 0.040 0.004 ind_n_pop_classes.py:35(evaluate)
10 0.004 0.000 1.071 0.107 ind_n_pop_classes.py:63(selection)
10 0.026 0.003 0.317 0.032 ind_n_pop_classes.py:67(crossover)
18011 0.074 0.000 0.079 0.000 random.py:147(randrange)
18011 0.023 0.000 0.102 0.000 random.py:211(randint)
10 0.081 0.008 1.067 0.107 selections.py:7(tournamentSelection)
1 0.001 0.001 1.428 1.428 test.py:39(main)
24000 0.033 0.000 0.033 0.000 {hasattr}
227953 0.042 0.000 0.042 0.000 {id}
18038 0.004 0.000 0.004 0.000 {len}
12008 0.004 0.000 0.004 0.000 {method 'add' of 'set' objects}
293953 0.085 0.000 0.085 0.000 {method 'append' of 'list' objects}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
203953 0.061 0.000 0.061 0.000 {method 'get' of 'dict' objects}
6000 0.002 0.000 0.002 0.000 {method 'iteritems' of 'dict' objects}
141011 0.032 0.000 0.032 0.000 {method 'random' of '_random.Random' objects}
6000 0.006 0.000 0.006 0.000 {method 'update' of 'dict' objects}
21 0.000 0.000 0.000 0.000 {range}
6600 0.012 0.000 0.012 0.000 {sum}
3000 0.017 0.000 0.017 0.000 {zip}
Yes, I used the deepcopy method because it was nice and make my live easy. Yup, big mistake. That force my selection to take almost 67% of the overall execution time. Quite unacceptable. Thanks to the profiler, now I knew were to look for slowness and more important, I learn what Python blanks in my knowledge need to be improved :D