stacklog

Nested benchmarking and timing code.

Stacklog uses a Logger object to capture timing output, so you can use multiple logging objects at once. The simplest interface is at the module level, and uses the 'default' Logger.



In [1]:

    
import stacklog
import time

def comp(t=.1):
    time.sleep(t)

The Logger accumulates input, but we can make sure we have an empty log with reset.



In [2]:

    
stacklog.reset()

tic() and toc() can be used to time a section of code
tic() needs a key to identify the result in a dictionary
multiple timings with the same key get appended to a list
log() is an interface to the dictionary of all the Logger objects
without arguments log() returns the default Logger (same as log('default'))



In [13]:

    
from stacklog import tic, toc, log, reset

reset()

# normal tic and toc for timing
tic('test1')
comp()
toc()

# with the same key, times get appended to a list
tic('multi')
comp()
toc()

tic('multi')
comp()
toc()

tic('multi')
comp()
toc()

# pretty print the result
log()









    Out[13]:





Stack item 0:

{'multi': [0.1091299057006836, 0.11002206802368164, 0.10144186019897461],
 'test1': 0.10390782356262207}

the Logger contains a dictionary of all recorded timings
peek exposes that dictionary without reseting it
pull exposes the dictionary and reset the Logger
pretty_dict will attemp to pretty print the dictionary
pretty_dict's clean argument defaults to True, which will remove empty data structures and replace single-element lists with their value



In [8]:

    
from stacklog import peek, pull, pretty_dict

# grab the dictionary of the log
result = peek()

# print the full data structure
pretty_dict(result, clean=False)
print "#"*10

# pretty print a cleaned up version (removing empty containers and extra parens)
pretty_dict(result)









    



{'multi': [(0.10065293312072754, {}),
           (0.10074996948242188, {}),
           (0.10254788398742676, {})],
 'test1': [(0.10051989555358887, {})]}
##########
{'multi': [0.10065293312072754, 0.10074996948242188, 0.10254788398742676],
 'test1': 0.10051989555358887}

we can also use the timer context manager and the with statement instead of tic and toc



In [9]:

    
from stacklog import timer

# can also use a context manager to time instead of tic and toc
with timer('something new'):
    comp()

log()









    Out[9]:





Stack item 0:

{'multi': [0.10065293312072754, 0.10074996948242188, 0.10254788398742676],
 'something new': 0.10142993927001953,
 'test1': 0.10051989555358887}

pull returns the Logger's dictionary and resets the log



In [11]:

    
result1 = pull()
pretty_dict(result1)

print "#"*10

with timer('all alone'):
    comp()
    
peek()









    



{'multi': [0.10065293312072754, 0.10074996948242188, 0.10254788398742676],
 'something new': 0.10142993927001953,
 'test1': 0.10051989555358887}
##########






    Out[11]:





{'all alone': [(0.10231685638427734, {})]}

nested timing

nesting tic/toc and timer creates more complicated, hierarchical timing structures



In [15]:

    
reset()

with timer('outer'):
    tic('inner')
    comp()
    toc()
    
    with timer('another inner'):
        comp()
        comp()
        comp()
        for i in range(4):
            with timer('way in there'):
                comp()

pretty_dict(peek())









    



{'outer': (0.8253848552703857,
           {'another inner': (0.7232990264892578,
                              {'way in there': [0.1048269271850586,
                                                0.1003260612487793,
                                                0.10056900978088379,
                                                0.10022306442260742]}),
            'inner': 0.10188698768615723})}

we can use lost_time to see the difference between a parent timer and the sum of its children to see how much time is unaccounted for



In [19]:

    
from stacklog import lost_time

lost_time(peek())









    Out[19]:





{'outer': [(0.00019884109497070312,
   {'another inner': [(0.3173539638519287, {})]})]}

we can also use pretty_dict with the output of lost_time



In [20]:

    
pretty_dict(lost_time(peek()))









    



{'outer': (0.00019884109497070312, {'another inner': 0.3173539638519287})}

notice that outer has very little unaccounted time
this is because the 'outer' timer is about equal to the sum of its children 'another inner' and 'inner'
however, the lost time for 'another inner' is about .3 seconds, which is exactly how long the untimed comp() functions should take to execute
if we account for them, we shoun't have such a large loss



In [21]:

    
reset()

with timer('outer'):
    tic('inner')
    comp()
    toc()
    
    with timer('another inner'):
        with timer('previously unaccounted for'):
            comp()
            comp()
            comp()
        for i in range(4):
            with timer('way in there'):
                comp()

pretty_dict(peek())









    



{'outer': (0.8192839622497559,
           {'another inner': (0.7142300605773926,
                              {'previously unaccounted for': 0.3051471710205078,
                               'way in there': [0.10043597221374512,
                                                0.10362792015075684,
                                                0.10380291938781738,
                                                0.10069108009338379]}),
            'inner': 0.10493993759155273})}

we see that all the times add up as expected



In [22]:

    
pretty_dict(lost_time(peek()))









    



{'outer': (0.00011396408081054688, {'another inner': 0.0005249977111816406})}

`Logger` interface

You can use multiple Loggers at once, by calling the member methods of the Logger objects.



In [3]:

    
from stacklog import Logger

a = Logger()
b = Logger()

a.tic('outer')
comp()
b.tic('something else')
comp()
comp()
comp()
a.toc()
comp()
comp()
b.toc()

print a
print b









    



Stack item 0:

{'outer': 0.41005778312683105}
Stack item 0:

{'something else': 0.5142879486083984}

function decorators

TODO