Bases: object
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
Ignore subroutines of "c" and "f" that are unnecessary for this comparison
Flatten the hierarchical timing information
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).
-
__init__()[source]
Methods
Member Documentation
-
clear_except(*args)[source]
Prune all “sub-timers” except those specified
- Parameters:
args (str) – Keys that will be retained
-
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.
-
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_timers()[source]
- Returns:
identifiers – Returns a list of all timer identifiers
- Return type:
list of str
-
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_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
-
reset()[source]
Completely reset the timer.
-
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