Desired utilities for hierarchical timer

[Robbybp]

Summary

I would like the ability to do two things with hierarchical timers:

• Flatten the timer
• Remove nodes from the timer

Motivation

I am benchmarking the ExternalPyomoModel implicit function interface and collecting hierarchical timing statistics that look like this:

To generate performance comparisons, I would like to flatten these timing statistics such that they form a partition of total time. This gives me a performance comparison that looks like this:

But this has many more categories than I need and is hard to read, so I would like to remove nodes in the timer except for categories that I care about. This gives me a performance comparison that looks like this:

I'm opening this issue to discuss whether these make sense as general utilities.

[Robbybp]

Another utility that would be useful would be the ability to start/stop a timer with a context manager, e.g.

>>> with timer.context("a"):
>>>     sleep(0.1)
>>> print(timer)
Identifier   ncalls   cumtime   percall      %
-----------------------------------------
a            1     0.100     0.100  100.0
=========================================

[michaelbynum]

I think a flattening utility makes a lot of sense. There are several utilities already in place that should make it fairly easy (I have done something similar before):

from pyomo.common.timing import HierarchicalTimer
from time import sleep


timer = HierarchicalTimer()
timer.start('all')
timer.start('a')
timer.start('aa')
sleep(0.1)
timer.stop('aa')
for i in range(10):
    timer.start('ab')
    sleep(0.03)
    timer.stop('ab')
sleep(0.05)
timer.stop('a')
timer.start('b')
sleep(0.1)
timer.stop('b')
timer.stop('all')
print(timer)

print('time in all.a.ab: ', timer.get_total_time('all.a.ab'))
print('number of calls in all.a.ab: ', timer.get_num_calls('all.a.ab'))
print('relative % time in all.a.ab: ', timer.get_relative_percent_time('all.a.ab'))
print('total % time in all.a.ab: ', timer.get_total_percent_time('all.a.ab'))

print('all timer names:')
for name in timer.get_timers():
    print('  ', name)

results in

Identifier        ncalls   cumtime   percall      %
---------------------------------------------------
all                    1     0.587     0.587  100.0
     ----------------------------------------------
     a                 1     0.484     0.484   82.4
          -----------------------------------------
          aa           1     0.103     0.103   21.3
          ab          10     0.331     0.033   68.3
          other      n/a     0.050       n/a   10.4
          =========================================
     b                 1     0.103     0.103   17.6
     other           n/a     0.000       n/a    0.0
     ==============================================
===================================================

time in all.a.ab:  0.33073045299999987
number of calls in all.a.ab:  10
relative % time in all.a.ab:  68.32940292945409
total % time in all.a.ab:  56.32774490815372
all timer names:
   all
   all.a
   all.a.aa
   all.a.ab
   all.b

I'm not sure if it makes more sense to drop nodes out of the timer or to simply skip certain nodes when flattening.

I definitely think a context manager would be useful.

[michaelbynum]

We also need to fix the indentation. I think the indentation should be fixed to 4 spaces.

[jsiirola]

FWIW, the logic for fixed 4-space indentation is already there (it gets turned on automatically for deep / wide printouts). We could just fix it to always use that mode.

[michaelbynum]

Oh! That's awesome! We should definitely use that mode by default, I think.

[Robbybp]

#2651 has been merged, which covers the basic utilities I initially wanted, so I'm closing this issue.