Non-linear increase of execution time when generating more toys

[nikoladze]

Hi,

I noticed that generating toy MC is becoming slower and slower the more toys were generated. An older thread seems to adress a similiar issue:

https://root-forum.cern.ch/t/how-to-speed-up-rooabspdf-createnll-procedure/10668

However, i couldn’t find a solution there. Is there any way to generate many toys in a single process without slowing down?

An example for this issue is attached (using the model from rf801_mcstudy.C) toy_runtime.C (2.0 KB)

It shows the time needed to generate 100 toys - one can see a continuous increase:

Generated 1600 toys 
Time per 100 toys: 0.488258
Generated 1700 toys 
Time per 100 toys: 0.514072
Generated 1800 toys 
Time per 100 toys: 0.518743
Generated 1900 toys 
Time per 100 toys: 0.537651
Generated 2000 toys 
Time per 100 toys: 0.55327
Generated 2100 toys 
Time per 100 toys: 0.580467
Generated 2200 toys 
Time per 100 toys: 0.608014
Generated 2300 toys 
Time per 100 toys: 0.607657
Generated 2400 toys 
Time per 100 toys: 0.636158
Generated 2500 toys 
Time per 100 toys: 0.645471
Generated 2600 toys 
Time per 100 toys: 0.665117
Generated 2700 toys 
Time per 100 toys: 0.680735
Generated 2800 toys 
Time per 100 toys: 0.703372
Generated 2900 toys 
Time per 100 toys: 0.730235
Generated 3000 toys 
Time per 100 toys: 0.755849
Generated 3100 toys 
Time per 100 toys: 0.794415
Generated 3200 toys 
Time per 100 toys: 0.801011
Generated 3300 toys 
Time per 100 toys: 0.82177
Generated 3400 toys 
Time per 100 toys: 0.848081

Cheers,

Nikolai

[nikoladze]

Some important extra information: I noticed this seems to become that bad only starting from ROOT 6.11

In root 6.10.08 the increase of processing time per 100 toys in the script above is starting from around 0.17s to 0.24s, which might be ok

In root 6.11.02 (and also 6.12.04) it is increasing from around 0.17s to up to 1.6s! This is a drastic increase, the total execution time of the script increases from 23s to 1min31s

So maybe it is a bug introduced in root 6.11?

[moneta]

Hi,

This is a side effect of the changes introduced in TList::RecursiveRemove, because the time is all spent in the destructor of the TFoam object.

Lorenzo

@pcanal

[moneta]

For @pcanal
Here is the output obtained by profiling the code

[fhoenig]

I’m curious, which tool did you use to generate this profiling output?

[moneta]

This comes from the Time Profiler of Instruments available as a developer tool on MacOS
Cheers

Lorenzo