pyomo.common.timing

A module of utilities for collecting timing information

report_timing([stream, level])

TicTocTimer([ostream, logger])

A class to calculate and report elapsed time.

tic([msg, ostream, logger, level])

Reset the global TicTocTimer instance.

toc([msg, delta, ostream, logger, level])

Print the elapsed time from the global TicTocTimer instance.

HierarchicalTimer()

A class for collecting and displaying hierarchical timing information
class pyomo.common.timing.TicTocTimer(ostream=NOTSET, logger=None)[source]

A class to calculate and report elapsed time.

Examples

>>> from pyomo.common.timing import TicTocTimer
>>> timer = TicTocTimer()
>>> timer.tic('starting timer') # starts the elapsed time timer (from 0)
[    0.00] starting timer
>>> # ... do task 1
>>> dT = timer.toc('task 1')
[+   0.00] task 1
>>> print("elapsed time: %0.1f" % dT)
elapsed time: 0.0

If no ostream or logger is provided, then output is printed to sys.stdout

Parameters:

  • ostream (FILE) – an optional output stream to print the timing information

  • logger (Logger) – an optional output stream using the python logging package. Note: the timing logged using logger.info()

tic(msg=NOTSET, *args, ostream=NOTSET, logger=NOTSET, level=NOTSET)[source]

Reset the tic/toc delta timer.

This resets the reference time from which the next delta time is calculated to the current time.

Parameters:

  • msg (str) – The message to print out. If not specified, then prints out “Resetting the tic/toc delta timer”; if msg is None, then no message is printed.

  • *args (tuple) – optional positional arguments used for %-formatting the msg

  • ostream (FILE) – an optional output stream (overrides the ostream provided when the class was constructed).

  • logger (Logger) – an optional output stream using the python logging package (overrides the ostream provided when the class was constructed). Note: timing logged using logger.info

  • level (int) – an optional logging output level.

toc(msg=NOTSET, *args, delta=True, ostream=NOTSET, logger=NOTSET, level=NOTSET)[source]

Print out the elapsed time.

This resets the reference time from which the next delta time is calculated to the current time.

Parameters:

  • msg (str) – The message to print out. If not specified, then print out the file name, line number, and function that called this method; if msg is None, then no message is printed.

  • *args (tuple) – optional positional arguments used for %-formatting the msg

  • delta (bool) – print out the elapsed wall clock time since the last call to tic() (False) or since the most recent call to either tic() or toc() (True (default)).

  • ostream (FILE) – an optional output stream (overrides the ostream provided when the class was constructed).

  • logger (Logger) – an optional output stream using the python logging package (overrides the ostream provided when the class was constructed). Note: timing logged using level

  • level (int) – an optional logging output level.

pyomo.common.timing.tic(msg=NOTSET, *args, ostream=NOTSET, logger=NOTSET, level=NOTSET)

Reset the global TicTocTimer instance.

See TicTocTimer.tic().

pyomo.common.timing.toc(msg=NOTSET, *args, delta=True, ostream=NOTSET, logger=NOTSET, level=NOTSET)

Print the elapsed time from the global TicTocTimer instance.

See TicTocTimer.toc().

class pyomo.common.timing.HierarchicalTimer[source]

A class for collecting and displaying hierarchical timing information

When implementing an iterative algorithm with nested subroutines (e.g. an optimization solver), we often want to know the cumulative time spent in each subroutine as well as this time as a proportion of time spent in the calling routine. This class collects timing information, for user-specified keys, that accumulates over the life of the timer object and preserves the hierarchical (nested) structure of timing categories.

Examples

>>> import time
>>> from pyomo.common.timing import HierarchicalTimer
>>> timer = HierarchicalTimer()
>>> timer.start('all')
>>> time.sleep(0.2)
>>> for i in range(10):
...     timer.start('a')
...     time.sleep(0.1)
...     for i in range(5):
...         timer.start('aa')
...         time.sleep(0.01)
...         timer.stop('aa')
...     timer.start('ab')
...     timer.stop('ab')
...     timer.stop('a')
...
>>> for i in range(10):
...     timer.start('b')
...     time.sleep(0.02)
...     timer.stop('b')
...
>>> timer.stop('all')
>>> print(timer)       
Identifier        ncalls   cumtime   percall      %
---------------------------------------------------
all                    1     2.248     2.248  100.0
     ----------------------------------------------
     a                10     1.787     0.179   79.5
          -----------------------------------------
          aa          50     0.733     0.015   41.0
          ab          10     0.000     0.000    0.0
          other      n/a     1.055       n/a   59.0
          =========================================
     b                10     0.248     0.025   11.0
     other           n/a     0.213       n/a    9.5
     ==============================================
===================================================

The columns are:

ncalls

The number of times the timer was started and stopped

cumtime

The cumulative time (in seconds) the timer was active (started but not stopped)

percall

cumtime (in seconds) / ncalls

“%”

This is cumtime of the timer divided by cumtime of the parent timer times 100

>>> print('a total time: %f' % timer.get_total_time('all.a'))         
a total time: 1.902037
>>> print('ab num calls: %d' % timer.get_num_calls('all.a.ab'))         
ab num calls: 10
>>> print('aa %% time: %f' % timer.get_relative_percent_time('all.a.aa'))         
aa % time: 44.144148
>>> print('aa %% total: %f' % timer.get_total_percent_time('all.a.aa'))         
aa % total: 35.976058

When implementing an algorithm, it is often useful to collect detailed hierarchical timing information. However, when communicating a timing profile, it is often best to retain only the most relevant information in a flattened data structure. In the following example, suppose we want to compare the time spent in the "c" and "f" subroutines. We would like to generate a timing profile that displays only the time spent in these two subroutines, in a flattened structure so that they are easy to compare. To do this, we

  1. Ignore subroutines of "c" and "f" that are unnecessary for this comparison

  2. Flatten the hierarchical timing information

  3. Eliminate all the information we don’t care about

>>> import time
>>> from pyomo.common.timing import HierarchicalTimer
>>> timer = HierarchicalTimer()
>>> timer.start("root")
>>> timer.start("a")
>>> time.sleep(0.01)
>>> timer.start("b")
>>> timer.start("c")
>>> time.sleep(0.1)
>>> timer.stop("c")
>>> timer.stop("b")
>>> timer.stop("a")
>>> timer.start("d")
>>> timer.start("e")
>>> time.sleep(0.01)
>>> timer.start("f")
>>> time.sleep(0.05)
>>> timer.stop("f")
>>> timer.start("c")
>>> timer.start("g")
>>> timer.start("h")
>>> time.sleep(0.1)
>>> timer.stop("h")
>>> timer.stop("g")
>>> timer.stop("c")
>>> timer.stop("e")
>>> timer.stop("d")
>>> timer.stop("root")
>>> print(timer) 
Identifier                       ncalls   cumtime   percall      %
------------------------------------------------------------------
root                                  1     0.290     0.290  100.0
     -------------------------------------------------------------
     a                                1     0.118     0.118   40.5
          --------------------------------------------------------
          b                           1     0.105     0.105   89.4
               ---------------------------------------------------
               c                      1     0.105     0.105  100.0
               other                n/a     0.000       n/a    0.0
               ===================================================
          other                     n/a     0.013       n/a   10.6
          ========================================================
     d                                1     0.173     0.173   59.5
          --------------------------------------------------------
          e                           1     0.173     0.173  100.0
               ---------------------------------------------------
               c                      1     0.105     0.105   60.9
                    ----------------------------------------------
                    g                 1     0.105     0.105  100.0
                         -----------------------------------------
                         h            1     0.105     0.105  100.0
                         other      n/a     0.000       n/a    0.0
                         =========================================
                    other           n/a     0.000       n/a    0.0
                    ==============================================
               f                      1     0.055     0.055   31.9
               other                n/a     0.013       n/a    7.3
               ===================================================
          other                     n/a     0.000       n/a    0.0
          ========================================================
     other                          n/a     0.000       n/a    0.0
     =============================================================
==================================================================
>>> # Clear subroutines under "c" that we don't care about
>>> timer.timers["root"].timers["d"].timers["e"].timers["c"].timers.clear()
>>> # Flatten hierarchy
>>> timer.timers["root"].flatten()
>>> # Clear except for the subroutines we care about
>>> timer.timers["root"].clear_except("c", "f")
>>> print(timer) 
Identifier   ncalls   cumtime   percall      %
----------------------------------------------
root              1     0.290     0.290  100.0
     -----------------------------------------
     c            2     0.210     0.105   72.4
     f            1     0.055     0.055   19.0
     other      n/a     0.025       n/a    8.7
     =========================================
==============================================

Notes

The HierarchicalTimer uses a stack to track which timers are active at any point in time. Additionally, each timer has a dictionary of timers for its children timers. Consider

>>> timer = HierarchicalTimer()
>>> timer.start('all')
>>> timer.start('a')
>>> timer.start('aa')

After the above code is run, timer.stack will be ['all', 'a', 'aa'] and timer.timers will have one key, 'all' and one value which will be a _HierarchicalHelper. The _HierarchicalHelper has its own timers dictionary:

{'a': _HierarchicalHelper}

and so on. This way, we can easily access any timer with something that looks like the stack. The logic is recursive (although the code is not).

start(identifier)[source]

Start incrementing the timer identified with identifier

Parameters:

identifier (str) – The name of the timer

stop(identifier)[source]

Stop incrementing the timer identified with identifier

Parameters:

identifier (str) – The name of the timer

reset()[source]

Completely reset the timer.

get_total_time(identifier)[source]
Parameters:

identifier (str) – The full name of the timer including parent timers separated with dots.

Returns:

total_time – The total time spent with the specified timer active.

Return type:

float

get_num_calls(identifier)[source]
Parameters:

identifier (str) – The full name of the timer including parent timers separated with dots.

Returns:

n_calls – The number of times start was called for the specified timer.

Return type:

int

get_relative_percent_time(identifier)[source]
Parameters:

identifier (str) – The full name of the timer including parent timers separated with dots.

Returns:

percent_time – The percent of time spent in the specified timer relative to the timer’s immediate parent.

Return type:

float

get_total_percent_time(identifier)[source]
Parameters:

identifier (str) – The full name of the timer including parent timers separated with dots.

Returns:

percent_time – The percent of time spent in the specified timer relative to the total time in all timers.

Return type:

float

get_timers()[source]
Returns:

identifiers – Returns a list of all timer identifiers

Return type:

list of str

flatten()[source]

Flatten the HierarchicalTimer in-place, moving all the timing categories into a single level

If any timers moved into the same level have the same identifier, the total_time and n_calls fields are added together. The total_time of a “child timer” that is “moved upwards” is subtracted from the total_time of that timer’s original parent.

clear_except(*args)[source]

Prune all “sub-timers” except those specified

Parameters:

args (str) – Keys that will be retained