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 ...
Updated 2019-11-09 adding last_day_summary_done
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' : {},
'last_day_summary_done': 0,
}
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 once, 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().date() == c.timer['end_dt'].date(): # Log summary on last day
if c.timer['last_day_summary_done']: return # Only once on 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'
))
c.timer['last_day_summary_done'] = True 
