Implement ComputationTimeSummary similar to ProfilingSummary

[denisalevi]

Hi @mstimberg,

I implemented a ComputationTimeSummary for my talk yesterday. I would like to get that into Brian, I find it useful for Brian2CUDA (to know why a small, short simulation is taking unexpectedly long e.g.).

Usage:

run(...)
print(computation_time_summary())

Output:

Computation time summary
========================
Compilation           4.20 s     0.39 %
Initialization        2.29 s     0.21 %
Simulation loop    1070.90 s    99.28 %
Finalization          1.31 s     0.12 %

I made a quick patch for my talk here, but would place it somewhere else probably and also remove the hard coded print of course. Here is my implementation: 251a995

For this implementation, I just copied the timing code from my benchmark scripts. Its probably unnecessary to use chrono here, a std::clock ist probably a bit easier? Actually, I just realized that we don't need any timer in generated code at all... We already have _last_run_time and the python timer of the binary execution. I'll updated my implementation accordingly.

What is the best place to put this? Maybe brian2/device/device.py? Any other additions other than what I implemented above? Only makes sense for standalone I guess.

[denisalevi]

Ah wait, if we don't add timers before and after network.run() in the generated code, we can't separate Initialization and Finalization. But that wouldn't matter I guess, would look like this then:

Computation time summary
========================
Compilation                          4.20 s     0.39 %
Initialization & Finalization        2.29 s     0.21 %
Simulation loop                   1070.90 s    99.28 %

Any opinions on the names here?

[mstimberg]

I wonder, maybe it would make sense to integrate this with the profiling system (and ProfilingSummary)? So for profile=False, it would give the information from your last comment, since we don't have any additional timing information, and for profile=True it would do the usual detailed profiling and integrate it in the above view. I think it would also make sense to have this for runtime mode, since compilation times for Cython can be significant, and sometimes it is hard to see whether it is the compilation or e.g. synapse generation that takes up so much time.

[denisalevi]

Good idea. Could even add profiling of before/after codeobjects that run outside the clock as detailed summary of the init/finalization timer (e.g. synapse generation of all synapse objects).

What would be the format?

Computation time summary
========================
Compilation                          4.20 s     0.39 %
Initialization & Finalization        2.29 s     0.21 %
Simulation loop                   1070.90 s    99.28 %

Simulation loop
========================
neurongroup_stateupdater ...
neurongroup_thresholder ...

Or rather some nested table (which would require changing the ProfilingSummary class)?

Should probably not change the device.profiling_info for backward compatibility, right? So just modifying what profiling_summary prints out?

[mstimberg]

Or rather some nested table (which would require changing the ProfilingSummary class)?

I was more thinking of a nested table, but it could also be just sequential, as in your example. We need to change ProfilingSummary in either case, no?

Should probably not change the device.profiling_info for backward compatibility, right? So just modifying what profiling_summary prints out?

Hmm, yes, probably. I doubt many people have been using it, but better to err on the side of caution here.