pyomo.common.timing

pyomo.common.timing.report_timing(stream=True, level=20)

Set reporting of Pyomo timing information.

Parameters:

• stream (bool, TextIOBase) – The destination stream to emit timing information. If True, defaults to sys.stdout. If False or None, disables reporting of timing information.
• level (int) – The logging level for the timing logger

class pyomo.common.timing.TicTocTimer(ostream=NOTSET, logger=None)

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)

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)

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

A class for hierarchical timing.

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

Notes

The HierarchicalTimer use 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)

Start incrementing the timer identified with identifier

Parameters:identifier (str) – The name of the timer

stop(identifier)

Stop incrementing the timer identified with identifier

Parameters:identifier (str) – The name of the timer

reset()

Completely reset the timer.

get_total_time(identifier)

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)

Parameters:identifier (str) – The full name of the timer including parent timers separated with dots. Returns:num_calss – The number of times start was called for the specified timer. Return type:int

get_relative_percent_time(identifier)

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)

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()

Returns:identifiers – Returns a list of all timer identifiers Return type:list of str