Profiling information is obtained by calling the module cProfile and by injecting specific code. The two most interesting methods to profile are flush and compile. The most important number from the profiling information is the amount of function calls, and reducing it results in noticeable speedups. Here is an example on the method compile:
import Build
def ncomp(self):
import cProfile, pstats
cProfile.run('import Build; Build.bld.rep_compile()', 'profi.txt')
p = pstats.Stats('profi.txt')
p.sort_stats('time').print_stats(150)
Build.bld.rep_compile = Build.bld.compile
Build.bld.compile = ncomp
Here the output obtained on a benchmark build created as explained in the previous section:
Sun Nov 9 19:22:59 2008 prof.txt
959695 function calls (917845 primitive calls) in 3.195 CPU seconds
Ordered by: internal time
List reduced from 187 to 10 due to restriction 10
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.531 0.531 0.531 0.531 {cPickle.dump}
73950/42150 0.223 0.000 0.276 0.000 Environment.py:66(__getitem__)
5000 0.215 0.000 0.321 0.000 Task.py:770(compute_sig_implicit_deps)
204434 0.180 0.000 0.180 0.000 {method 'update' of '_hashlib.HASH' objects}
5050 0.170 0.000 0.551 0.000 Task.py:706(sig_vars)
10000 0.144 0.000 0.301 0.000 Utils.py:98(h_file)
25255/15205 0.113 0.000 0.152 0.000 Node.py:329(abspath)
15050 0.107 0.000 0.342 0.000 Task.py:481(unique_id)
15301 0.102 0.000 0.102 0.000 Environment.py:50(variant)
132062 0.097 0.000 0.097 0.000 {method 'get' of 'dict' objects}
From the profile information, it appears that the hot spots are, in order:
In practice, the time taken by these methods is not significant enough to justify code changes. Also, profiling must be carried out on builds which last at least several seconds.