Use decorator function to compare execution times

Question

After coming across this excellent explanation about decorators, I realized decorators can be quite useful to display function execution times. My ultimate goal is to create a function

compare_functions(f1, f2) 

that compares the execution times of two functions f1 and f2. As a start I designed this decorator:

def clean_exec_time(fnc):
    def wrapper(*args):
        t0 = time.perf_counter()
        fnc(*args)
        t1 = time.perf_counter()
        print(t1-t0)
return wrapper

Which can be used perfectly in this way:

@clean_exec_time
def print_msg(msg):
    print(msg)

Such that

print_msg('Hi') 
# outputs:
# Hi
# 3.0109e-05

That's great. It get's tricky (for me) when I try to work my way to the ultimate goal.

@clean_exec_time
def compare_functions(f1, f2): 
    a = 2 #not sure what to put here

Now I see the following:

compare_functions(print_msg('Hi'), print_msg('See ya'))
# outputs
# Hi
# 3.0793e-05
# See ya
# 1.1291e-05
# 6.5010e-05

I have a few questions:

1. Why are 2 execution times printed after 'See ya'?
2. What do I need to modify in order to see a value c printed that denotes the number of times f1 is faster/slower than f2.
3. It feels strange not to put anything meaningful in my function compare_functions. Is there an elegant way to cope with this?

Answer 1

As discussed, one possibility is to use lambdas as arguments:

def compare_time(f1, f2):
    t0 = time.perf_counter()
    f1()
    t1 = time.perf_counter()
    f2()
    t2 = time.perf_counter()
    print(f"Time diff is {(t1 - t0) - (t2 - t1)} s")

compare_time(lambda: print_msg('Hi'), lambda: print_msg('See ya'))

This gives:

Hi
See ya
Time diff is 1.9200000000010875e-05 s

Unfortunately, lambda functions do not have information about the called function. If you need this, here is a hacky solution, that takes the strings of the functions calls:

def compare_time1(f1, f2):
    t0 = time.perf_counter()
    eval(f1)
    t1 = time.perf_counter()
    eval(f2)
    t2 = time.perf_counter()
    print(f"Time diff between {f1} and {f2} is {(t1 - t0) - (t2 - t1)} s")

compare_time1("print_msg('Hi')", "print_msg('See ya')")

This gives:

Hi
See ya
Time diff between print_msg('Hi') and print_msg('See ya') is 3.0000000000002247e-05 s

Another possibility is to separate function names and arguments - not so hacky, but also not very convenient:

def compare_time2(f1, args1, f2, args2):
    t0 = time.perf_counter()
    f1(*args1)
    t1 = time.perf_counter()
    f2(*args2)
    t2 = time.perf_counter()
    print(f"Time diff between {f1.__name__}({str(args1)[1:-1]}) and"
          f" {f2.__name__}({str(args2)[1:-1]}) is {(t1 - t0) - (t2 - t1)} s")

compare_time2(print_msg, ['Hi'], print_msg, ['See ya'])

This gives:

Hi
See ya
Time diff between print_msg('Hi') and print_msg('See ya') is 8.000000000091267e-07 s

Answer 2

compare_functions is the wrong function to decorate, because you want to time each of the functions being passed to compare_functions, not compare_functions itself.

I find it more useful to time code with a context manager.

import time
import contextlib


class TimeResult:
    def __init__(self):
        self._start = None
        self._stop = None

    def start(self):
        self._start = time.perf_counter()

    def stop(self):
        self._stop = time.perf_counter()

    @property
    def result(self):
        if self._start is None or self._stop is None:
            return None
        return self._stop - self._start

This is a simple class whose result property is None until after you've called both its start and stop methods (preferably in that order)

@contextlib.contextmanager
def timeit():
    t = TimeResult()
    t.start()
    yield t
    t.stop()

This creates a context manager that yields a TimeResult object whose start and stop methods are called at on entry to and on exit from a with statement, respectively.

def compare_functions(f1, f2): 
    with timeit() as t1:
        f1()

    print(f'Function 1 took {t1.result} seconds')

    with timeit() as t2:
        f2()

    print(f'Function 2 took {t2.result} seconds')

compare_functions takes two functions to call, and times each of them the the timeit context manager. As each function completes, the elapsed time is reported.

Then

def print_msg(msg):
    print(msg)

compare_functions(lambda: print_msg("hi"), lambda: print_msg("see ya"))

takes two functions to call and time.

Alternatively, you can pass the functions to time and the arguments separately, and let compare_functions combine them.

def compare_functions(f_and_args_1, f_and_args_2):
    f1, *args1 = f_and_args1
    f2, *args2 = f_and_args2

    with timeit() as t1:
        f1(*args1)

    print(f'{f1.__name__} took {t1.result} seconds')

    with timeit() as t2:
        f2(*args2)

    print(f'{f2.__name__} took {t2.result} seconds')



compare_functions((print_msg, "hi"), (print_msg, "see ya"))

Answer 3

For future reference, this is the what I've done (without decorators).

def compare_functions(f1, f2, reps=1):
    text_trap = io.StringIO()    # 
    sys.stdout = text_trap       # These two lines avoid print statements 
    fnc1 = get_func(f1)
    fnc2 = get_func(f2)
    c1 = get_exec_time(fnc1, reps)
    c2 = get_exec_time(fnc2, reps)
    sys.stdout = sys.__stdout__   # turn print statement back on
    if c1 > c2:
        print('Function {0} is {1:.2f} times faster than function {2}'.format(1, c1/c2, 2))
    if c2 > c1:
        print('Function {0} is {1:.2f} times faster than function {2}'.format(2, c2/c1, 1))

Where

def get_func(fnc):
    if not callable(fnc):
        return lambda: fnc
    else:
        return fnc

def get_system_speed():           #used as benchmark
    t0 = time.perf_counter()
    do_calc()                     #arbritrary function
    return time.perf_counter()-t0

def get_exec_time(fnc, reps=1):
    ex_times = []
    for i in range(reps):
        c = get_system_speed()
        t0 = time.perf_counter()
        fnc()
        ex_times.append((time.perf_counter()-t0)/c)
return np.average(ex_times)

This allows me to compare the execution times of two (lambda) functions, by executing each function reps times and benchmarking each run to the system speed at that moment. For example, using the print_msg function as above:

compare_functions(lambda: print_msg('hi'), lambda: print_msg('hi'), reps=10000)
# outputs
# Function 2 is 1.00 times faster than function 1

Thanks for the help and suggestions!