Decorator to time specific lines of the code instead of whole method?
You can use a context manager.
import contextlib
@contextlib.contextmanager
def time_measure(ident):
tstart = time.time()
yield
elapsed = time.time() - tstart
logger.debug("{0}: {1} ms".format(ident, elapsed))
In your code, you use it like
with time_measure('test_method:sum1'):
sum1 = sum(range(a, b))
By the way, if you want to improve your code, you can use the Gaussian Sum Formula (explained here) instead of sum(range(a, b))
.
def sum_range(a, b):
r_a = (a ** 2 + a) / 2 - a
r_b = (b ** 2 + b) / 2 - b
return r_b - r_a
One way I can think of is to use sys.settrace() and record time when handling "line" event in the tracer function. But one caveat is, the practice of setting a tracer may cause the time recorded to be inaccurate.
The general idea is:
- Set a tracer function in the decorator that wraps the target method.
- Get the line number for the first line of this method, with
FLN = inspect.currentframe().f_lineno.
- In the tracer function, handle "call" event and return a local tracer function to trace the "line" events in the scope. Read this if you are confused.
- Within the local tracer function, get the current line number LN, if LN-FLN == M, record the start time; if LN-FLN == N, record the end time, the time taken to execute lines M to N is endtime - starttime.
code:
import sys
from functools import wraps
import time
import linecache
_func_name_ = None
_func_ln_ = 0
_start_ = 0
_end_ = 0
_timestamp_ = 0
def trace_calls(frame, event, arg):
global _func_name_, _func_ln_
def trace_lines(frame, event, arg):
global _timestamp_
if event != 'line':
return
line_no = frame.f_lineno
filename = frame.f_code.co_filename
if line_no-_func_ln_ == _start_:
_timestamp_ = time.time()
print "%d %s TS:%d"%(line_no, linecache.getline(filename, line_no)[:-1], _timestamp_)
elif line_no-_func_ln_ == _end_:
_timestamp_ = time.time() - _timestamp_
print "%d %s"%(line_no, linecache.getline(filename, line_no)[:-1])
print "Lines %d to %d of %s takes %d seconds."%(_start_, _end_, _func_name_, _timestamp_)
if event != 'call':
return
co = frame.f_code
_func_ln_ = frame.f_lineno # record the line number at function entry point
func_name = co.co_name
if func_name != _func_name_:
return
return trace_lines
def time_lines(start, end):
global _start_, _end_
_start_, _end_ = start+1, end+2 # function name takes a line, end is inclusive
def inner(f):
@wraps(f)
def wrapper(*args, **kwargs):
global _func_name_
_func_name_ = f.__name__
sys.settrace(trace_calls)
f(*args, **kwargs)
sys.settrace(None)
return wrapper
return inner
@time_lines(2,4)
def tested_func():
print "Enter target function"
time.sleep(2)
time.sleep(1)
time.sleep(3)
print "Exit target function"
if __name__=="__main__":
tested_func()