Hand-crafted profiling

Just finished placing timers around all the ins and outs in my C code and formatting the outputs. Now the result of a single C vs Python run looks like

./c_vs_python.sh -m 100 -n 100 -i 30 -s examples/matchmodel.ty
TOPOGRAPHICA RUNS

### Python+C ###
Total script init time: 8.38710808754
Serial: 5.48633885384

real    0m14.301s
user    0m13.097s
sys     0m1.021s

### BARE C ###

====================== main() ======================
Total:                                  10.7808
----------------------------------------------------
Utils:                                  0.0557
Create and normalise CFs:               1.4893
Serial activate:                        4.6100
Barrier between serial and parallel:    0.0000
Parallel activate:                      4.6257
=================== activateSeq() ==================
Total:                                  4.6100
----------------------------------------------------
Utils:                                  0.0008
Dot product:                            4.6083
Output function:                        0.0008
=================== activateMPI() ==================
Total:                                  4.6257
----------------------------------------------------
Utils:                                  0.0065
Distributing weights:                   0.0001
Broadcasting inputs:                    0.0000
Dot product:                            4.6174
Gathering activity:                     0.0008
Output function:                        0.0008
====================================================

real    0m10.840s
user    0m10.484s
sys     0m0.303s

### Comparing results ###
Results matched

Timings are printed to screen only for the first node, although in this run I only used just one. For more detailed per-processor results (only for bare C code yet) the timings are printed into separate files (appending if the files exist) called timings.X.out where X corresponds to the rank of the node. A sample file might look like this:

#size 4
#m 100
#n 100
#i 20
main_tot 7.87351489
main_utils 1.07544136
main_create_cfs 0.00000095
main_seq_act 0.00000095
main_mpi_act 2.45419502
main_barrier 4.34387183
act_seq_tot 0.00000000
act_seq_utils 0.00000000
act_seq_dp 0.00000000
act_seq_of 0.00000000
act_mpi_tot 2.45419288
act_mpi_utils 0.00215340
act_mpi_distr_weights 1.10045886
act_mpi_bc 0.00546145
act_mpi_dp 1.34518266
act_mpi_gather 0.00084949
act_mpi_of 0.00001097
#end

I planned this to be more machine-readable for later use in two plotting scripts that I'm currently working on: one would take filename1 filename2 ... "param1 param2 ... >paramN" as arguments to produce N bars where params 1 through N-1 make up the total of paramN (e.g. timings.0.out timings.1.out "act_seq_utils act_seq_dp act_seq_of > act_seq_tot" should show two bars with utils, dot-product and output function displayed as percentages of the total serial activation time). The second script would work with scaling of one parameter against another. For example the total parallel activation time against the number of runs, the number of processors, or the size of the input sheet (m*n). That will be displayed in form of line graphs. Sounds like a lot of work, but in the end I will have a hand-crafted and very customisable set of profiling tools that do exactly what I need, should be worth the effort.