timeit versus timing decorator

user_190597 0
Viewed 121732

I'm trying to time some code. First I used a timing decorator:

#!/usr/bin/env python

import time
from itertools import izip
from random import shuffle

def timing_val(func):
    def wrapper(*arg, **kw):
        '''source: http://www.daniweb.com/code/snippet368.html'''
        t1 = time.time()
        res = func(*arg, **kw)
        t2 = time.time()
        return (t2 - t1), res, func.__name__
    return wrapper

@timing_val
def time_izip(alist, n):
    i = iter(alist)
    return [x for x in izip(*[i] * n)]

@timing_val
def time_indexing(alist, n):
    return [alist[i:i + n] for i in range(0, len(alist), n)]

func_list = [locals()[key] for key in locals().keys()
             if callable(locals()[key]) and key.startswith('time')]
shuffle(func_list)  # Shuffle, just in case the order matters

alist = range(1000000)
times = []
for f in func_list:
    times.append(f(alist, 31))

times.sort(key=lambda x: x[0])
for (time, result, func_name) in times:
    print '%s took %0.3fms.' % (func_name, time * 1000.)

yields

% test.py
time_indexing took 73.230ms.
time_izip took 122.057ms.

And here I use timeit:

%  python - m timeit - s '' 'alist=range(1000000);[alist[i:i+31] for i in range(0, len(alist), 31)]'
10 loops, best of 3:
    64 msec per loop
% python - m timeit - s 'from itertools import izip' 'alist=range(1000000);i=iter(alist);[x for x in izip(*[i]*31)]'
10 loops, best of 3:
    66.5 msec per loop

Using timeit the results are virtually the same, but using the timing decorator it appears time_indexing is faster than time_izip.

What accounts for this difference?

Should either method be believed?

If so, which?

timing timeit python
8 Answers

Inspired by Micah Smith's answer, I made funcy print directly instead (and not use logging module).

Below is convenient for use at google colab.

# pip install funcy
from funcy import print_durations

@print_durations()
def myfunc(n=0):
  for i in range(n):
    pass

myfunc(123)
myfunc(123456789)

# 5.48 mks in myfunc(123)
# 3.37 s in myfunc(123456789)
user_98685860

This is the type of need that you pray a library provides a portable solution -- DRY! Fortunately funcy.log_durations comes to the answer.

Example copied from documentation:

@log_durations(logging.info)
def do_hard_work(n):
    samples = range(n)
    # ...

# 121 ms in do_hard_work(10)
# 143 ms in do_hard_work(11)
# ...

Browse the funcy documentation for other variants such as different keyword arguments and @log_iter_durations.

user_25142280
Related