Back to Community
Timing Code

To identify slow areas and optimize.

Example output:

1970-01-01 timing:90 INFO 0.8800 avg 0.8800 lo 0.8800  hi 0.87998  init new max  
2015-10-01 timing:90 INFO 0.0013 avg 0.0013 lo 0.0013  hi 0.00133  volume new max  
2015-10-01 timing:90 INFO 0.0013 avg 0.0013 lo 0.0013  hi 0.00125  close new max  
2015-10-01 timing:90 INFO 0.1267 avg 0.1267 lo 0.1267  hi 0.12674  order new max

2015-12-28 timing:112 INFO Timing by highs descending:  
2015-12-28 timing:114 INFO avg 0.879977 lo 0.879977  hi 0.879977  init  
2015-12-28 timing:114 INFO avg 0.066348 lo 0.037155  hi 0.126741  order  
2015-12-28 timing:114 INFO avg 0.001009 lo 0.000823  hi 0.001328  volume  
2015-12-28 timing:114 INFO avg 0.000973 lo 0.000787  hi 0.001250  close

End of logs.  

Edit: Updated 2017-04-23. The example output above no longer matches, however this code is better ...

def rebalance(context):  
    timing(context, 'balancing', 'reset')

        #   ... [ code to be timed ] ...

    timing(context, 'balancing')

def handle_data(context, data):  
    #      id reset  
    #            \/        time to zero for this id  
    #            \/        \/  
    timing(c, 'prices', 'reset')                     # Reset time to zero, says to start.  
    prices = data.history(stocks, 'price', 1, '1d')  
    timing(c, 'prices') # -----|                     # Time since reset, does the logging.  
    #                      /\  
    #                      No reset this time


    timing(c, 'order', 'reset')

    for stock in context.portfolio.positions:  
        order_target(stock, 0)       # ordering

    timing(c, 'order')  
    #           /\  
    #        identifier

def timing(c, ident, reset=None):  # You set the id to any string you wish  
    '''   https://www.quantopian.com/posts/timing-code  
    Timing code to determine elapsed time for any given section of code.  
    Log timing between any 'reset' and its pair like timing(context, 'history1')  
    Time is in seconds, incoming 'c' is context  
    How to:  
        Start:   timing(context, 'some string', 'reset')  
        End:     timing(context, 'some string')  
          ... and the function def timing(), those are all you need.  
    There can be multiple instances with different ids ('some string', whatever you set).  
    The string identifier keeps them separate.  
    '''  
    from pytz     import timezone as _tz  
    from datetime import datetime as _dt  
    import time as _t         # Python will only bother doing once, makes this portable.  
                              #   Move to top of algo for better efficiency.  
    t = _t.time()  
    if 'timer' not in c:      # Also move these, to initialize() for better efficiency.  
        c.timer   = {         # Dictionary to keep track of these timings.  
            'log_level': 1,   # -1   Off  
                              #  0   Only summary at end of run  
                              #  1   Each new maximum  
                              #  2   Everything always  
                              #  3   Only if beyond a certain threshold. Use warn_threshold.  
            # Use with (3) log_level to only log if elapsed is above this seconds value.  
            'warn_threshold': 1.5,  
            'elapsed_start' : _t.time(),  
            'end_dt'        : get_environment('end'),  
            'ids': {},  
        }  
    if ident not in c.timer['ids']:  
        c.timer['ids'][ident] = {   # Initialization of any new id string  
            'point': t,  
            'hi'   : 0,  
            'lo'   : 1000,  
            'avg'  : [0, 0],  
        }  
        return  
    if c.timer['log_level'] == -1: return  
    if reset:  
        c.timer['ids'][ident]['point'] = t    # Point-in-time, acting as zero.  
        return  
    elapsed     = t - c.timer['ids'][ident]['point']      # Elapsed time  
    avg, num    = c.timer['ids'][ident]['avg']            # Tracking average  
    avg_new     = ((avg * num) + elapsed) / (num + 1)   # Calc new average  
    new_max_str = 'new max' if elapsed > c.timer['ids'][ident]['hi'] else ''  
    c.timer['ids'][ident]['avg'] = [avg_new, num + 1]     # New values  
    c.timer['ids'][ident]['hi']  = max(elapsed, c.timer['ids'][ident]['hi'])  
    c.timer['ids'][ident]['lo']  = min(elapsed, c.timer['ids'][ident]['lo'])  
    if (c.timer['log_level'] == 1 and new_max_str) or c.timer['log_level'] == 2 or (c.timer['log_level'] == 3 and elapsed > c.timer['warn_threshold']):  
      log.info('{} avg {} lo {}  hi {}  {} {}'.format('%.4f' % elapsed, '%.4f' % avg_new, '%.4f' % c.timer['ids'][ident]['lo'], '%.5f' % c.timer['ids'][ident]['hi'], ident, new_max_str))

    # Summary on last day minute, sorted by highest high value first.  
    # If using schedule_function(), backtest last day/time may need to match for this to execute.  
    if get_datetime() == c.timer['end_dt']:    # Log on last minute of last day  
        id_list = []  
        for i in c.timer['ids']:  
            hi = '%.6f' % c.timer['ids'][i]['hi']  
            lo = '%.6f' % c.timer['ids'][i]['lo']  
            av = '%.6f' % c.timer['ids'][i]['avg'][0]  
            id_list.append( (hi, lo, av, i) )  
        list_sort = sorted(id_list, reverse=True)  
        log.info('Timings by highs descending:')  
        for ls in list_sort:  
            log.info('avg {} lo {}  hi {}  {}'.format(ls[2],ls[1],ls[0],ls[3]))  
        elapsed = (_t.time() - c.timer['elapsed_start']) / 60  # minutes  
        log.info( '\nRuntime {} hr {} min    End: {} {}'.format(  
            int(elapsed / 60), '%02d' % (elapsed % 60),  
            _dt.now(_tz('US/Eastern')).strftime('%Y-%m-%d %H:%M'), 'US/Eastern'  
        ))  
1 response

beautiful!!

thanks!