2. Introductory Examples¶
2.1. Starting Simple¶
import gtimer as gt
import time
time.sleep(0.1)
gt.stamp('first')
time.sleep(0.3)
gt.stamp('second')
print gt.report()
>> ---Begin Timer Report (root)---
>> Timer Name: root (running)
>> Total Time (s): 0.4031
>> Stamps Sum: 0.4028
>> Self Time (Agg.): 4.792e-05
>>
>>
>> Intervals
>> ---------
>> first .............. 0.1024
>> second ............. 0.3004
>>
>> ---End Timer Report (root)---
The timer automatically starts on import, and each call to stamp() marks the end of an interval. The “Self Time” is how long was spent inside G-Timer functions, and has already been subtracted from the total. Times are always presented in units of seconds. The default timer name is “root”, and it is indicated that this timer was still running (i.e. has not been stopped)–reports can be generated at any time without interfering with timing.
(Internally, all timing is performed using default_timer() imported from timeit.)
2.2. Subdividing¶
import gtimer as gt
import time
# Could be in another file with gtimer import.
@gt.wrap
def func_1():
time.sleep(0.1)
gt.stamp('f_first')
def func_2():
time.sleep(0.1)
gt.stamp('f_inline')
time.sleep(0.1)
func_1()
gt.stamp('first')
func_2()
gt.stamp('second')
time.sleep(0.1)
gt.stamp('third', quick_print=True)
gt.subdivide('sub')
time.sleep(0.1)
func_1()
gt.stamp('sub_1')
time.sleep(0.1)
gt.stamp('sub_2')
gt.end_subdivision()
gt.stamp('fourth')
print gt.report()
>> (root) third: 0.1002
>>
>> ---Begin Timer Report (root)---
>> Timer Name: root (running)
>> Total Time (s): 0.7049
>> Stamps Sum: 0.7037
>> Self Time (Agg.): 0.0004189
>>
>>
>> Intervals
>> ---------
>> first .............. 0.2023
>> (func_1)
>> f_first ............ 0.1002
>> f_inline ........... 0.1002
>> second ............. 5.96e-06
>> third .............. 0.1002
>> fourth ............. 0.301
>> (sub)
>> sub_1 .............. 0.2006
>> (func_1)
>> f_first ............ 0.1002
>> sub_2 .............. 0.1002
>>
>> ---End Timer Report (root)---
Calls to stamp() always apply to the current level in the timer hierarchy. The time in the 'sub' subdivision was accumulated entirely within the span of the interval 'fourth' in the root timer. Subdivisions may be nested to any level, and subdivided times appear indented beneath the stamp to which they belong.
The negligible time of the interval 'second' resulted from in-line timing of the un-decorated func_2.
Using the quick_print flag in a stamp prints the elapsed interval time immediately.
IMPORTANT: Subdivisions are managed according to their names. Two separate subdivisions of the same name, occuring at the same level and between stamps in the surrounding timer, will be counted as two iterations of the same timer and their data merged. If this is not the intended outcome, use distinct names.
2.3. Timer Control¶
time.sleep(0.1)
gt.start()
time.sleep(0.1)
gt.stamp('first')
gt.pause()
time.sleep(0.1)
gt.resume()
gt.stamp('second')
time.sleep(0.1)
gt.blank_stamp('third')
time.sleep(0.1)
gt.stop('fourth')
time.sleep(0.1)
print gt.report()
>> ---Begin Timer Report (root)---
>> Timer Name: root
>> Total Time (s): 0.3006
>> Stamps Sum: 0.2004
>> Self Time (Agg.): 6.39e-05
>>
>>
>> Intervals
>> ---------
>> first .............. 0.1002
>> second ............. 5.96e-06
>> fourth ............. 0.1002
>>
>> ---End Timer Report (root)---
Calling start() ignores any previous time, the time between pause() and resume() is ignored, and so is any time after stop() (used here with an optional stamp name). The function blank_stamp() begins a new interval but discards the time data of the one it ends. There is finality in the stop() command–afterwords a timer level cannot be resumed, but it can be reset.
The “Stamps Sum” field indicates that the stamps data is not all-inclusive of the total time, due to the blank_stamp() call. This can also happen if stopping without stamping, or if no stamp is called immediately prior to enterting a timed loop.
2.4. Comparing Results¶
Use the get_times() function (or save_pkl(), load_pkl()) at the end of a completed timed run to retrieve the timing data. Collect results from multiple runs into a list and provide it to the compare() function to return a side-by-side comparison of timing data. For example, in an interactive session:
run example.py
gt.rename_root('run_1')
times_1 = gt.get_times()
run example.py
gt.rename_root('run_2')
times_2 = gt.get_times()
print gt.compare([times_1, times_2])
# inside example.py main:
gt.reset_root()
<body of script>
gt.stop()
>> run_1 run_2
>> ------- -------
>> Total............. 4.00 4.00
>> Stamps Sum........ 4.00 4.00
>>
>> another_method ... 1.00 1.00
>> some_function .... 3.00 3.00
>> some_method ...... 1.00 1.00
>> another_function . 2.00 2.00
>>
>>
>> Max Min Mean StDev Num
>> ------ ------ ------ ------ ------
>> Total ............ 4.00 4.00 4.00 0.00 2
>>
>>
>> another_method ... 1.00 1.00 1.00 0.00 2
>> some_function .... 3.00 3.00 3.00 0.00 2
>> some_method ...... 1.00 1.00 1.00 0.00 2
>> another_function . 2.00 2.00 2.00 0.00 2