View source for Speed profiling using TimingInfo and TimingDeltas classes

TimingInfo class provides per-engine information about the time it was running and how many times it was executed. TimingDeltas provide for much finer (but intrusive) way of checkpointing code and getting detailed information at the level of parts of functions.

== Usage ==

Timing information collection has to be turned on

<source lang="cpp"> TimingInfo::enabled=True; // c++</source>
<source lang="python"> O.timingEnabled=True # python </source>

Note that timing has some overhead. It is a few percent for plain TimingInfo (engine-level), It can be much more for TimingDeltas.

After running the simulation, you can get some simple statistics:
<source lang="python">
import yade.timing
timing.stats()
</source>

 Name                                                    Count                 Time            Rel. time
 -------------------------------------------------------------------------------------------------------
 PhysicalActionContainerReseter                      400               9380μs                0.01%      
 BoundingVolumeMetaEngine                            400            1162938μs                1.79%      
 PersistentSAPCollider                               400            9664181μs               14.90%      
 InteractionGeometryMetaEngine                       400           15401862μs               23.75%      
 InteractionPhysicsMetaEngine                        400            9709880μs               14.97%      
 ConstitutiveLawDispatcher                           400           26975622μs               41.59%      
 "damper"                                            400            1871791μs                2.89%      
 "strainer"                                          400              21561μs                0.03%      
 "plotDataCollector"                                 101              40705μs                0.06%      
 "damageChecker"                                       6               1967μs                0.00%      
 TOTAL                                                             64859892μs              100.00%      

If I want to see what happend inside the ConstitutiveLaw I use, I will add TimingDeltas to the c++ source (see below) to get:

 Name                                                    Count                 Time            Rel. time
 -------------------------------------------------------------------------------------------------------
 PhysicalActionContainerReseter                      400               9449μs                0.01%      
 BoundingVolumeMetaEngine                            400            1171770μs                1.15%      
 PersistentSAPCollider                               400            9433093μs                9.24%      
 InteractionGeometryMetaEngine                       400           15177607μs               14.87%      
 InteractionPhysicsMetaEngine                        400            9518738μs                9.33%      
 ConstitutiveLawDispatcher                           400           64810867μs               63.49%      
   ef2_Spheres_Brefcom_BrefcomLaw                                                                       
     setup                                           4926145            7649131μs               15.25%  
     geom                                            4926145           23216292μs               46.28%  
     material                                        4926145            8595686μs               17.14%  
     rest                                            4926145           10700007μs               21.33%  
     TOTAL                                                             50161117μs              100.00%  
 "damper"                                            400            1866816μs                1.83%      
 "strainer"                                          400              21589μs                0.02%      
 "plotDataCollector"                                 160              64284μs                0.06%      
 "damageChecker"                                       9               3272μs                0.00%      
 TOTAL                                                            102077490μs              100.00%      

* MetaEngine and ParallelEngine can have subordinated slaves/functors, in which case the table shows those as well in a tree-like fashion.
* TimingDeltas show in subordination to their containing Engine/EngineUnit. Here, the "ef2_Spheres_Brefcom_BrefcomLaw" has 4 checkpoints named "setup", "geom", "material" and "rest" (see below on details).

# Constitutive law takes over 60% now. This is because it containes TimingDeltas, which are '''very expensive''', since they are run 5e6 times (and it is just a few minutes of simulation)!!
# The proportions of checkpoints inside ef2_Spheres_Brefcom_BrefcomLaw are however realistic. I am for example told that almost half of the time (relative to ef2_Spheres_Brefcom_BrefcomLaw) is spent in the "geom" part, only 17% in the material law itself.
# I can compare total time for ef2_Spheres_Brefcom_BrefcomLaw::go and time that is spent in ConstitutiveDispatcher in total: 50.2sec vs. 64.8sec. The dispatcher therefore has overhead of about 10% of total simulation time (102sec) to do its job.

== TimingInfo ==
Each engine and EngineUnit contains TimingInfo object. Every time the engine is activated, nanosecond-resolution is requested from the system. When the engine returns, the durations is recorded to the engine's timingInfo and execCount is incremented. This can be queried using
<source lang="python">
someEngine.execTime # in nanoseconds
someEngine.execCount
</source>
To reset all timing data, say
<source lang="python">
yade.timing.reset() # traverses recursively all engines and functors and resets counts and times to 0
</source>

== TimingDeltas ==
TimingDeltas is an object that can be optionally held by any Engine or EngineUnit. Using special functions, labeled checkpoints are marked in the source code. As checkpoint is passed, the time since the last checkpoint is increased and execCount is incremented. Typically, you will use this to see which part of your funcion take the most time during execution.

First, I have to create the timingDeltas object before I use it, for example in the Engine's (or EngineUnit's) constructor:
<source lang="cpp">
class ef2_Spheres_Brefcom_BrefcomLaw: public  ConstitutiveLaw{
   public:
      ef2_Spheres_Brefcom_BrefcomLaw(): { timingDeltas=shared_ptr<TimingDeltas>(new TimingDeltas); }
   // ...
};
</source>
Then I will add checkpoints to the function I want to measure:
<source lang="cpp">
void ef2_Spheres_Brefcom_BrefcomLaw::go(shared_ptr<InteractionGeometry>& _geom, shared_ptr<InteractionPhysics>& _phys, Interaction* I, MetaBody* rootBody){
   timingDeltas->start(); // the point at which the first timing starts
   // prepare some variables etc here
   timingDeltas->checkpoint("setup");
   // find geometrical data (deformations) here
   timingDeltas->checkpoint("geom");
   // compute forces here
   timingDeltas->checkpoint("material");
   // apply forces, cleanup here
   timingDeltas->checkpoint("rest");
}
</source>

See TimingDeltas class for more information. This class can be also accessed from python:
<source lang="python">
deltas=someEngine.timingDeltas
deltas[0][0] # 0th checkpoint name
deltas[0][1] # 0th checkpoint time in nanoseconds
deltas[0][2] # 0th checkpoint execution count
deltas[1][0] # ...
##
yade.timing.reset() # resets also all timingDeltas
</source>
[[Category:Performance]]