Profiling

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.