timeit和timing装饰器的区别

118

我正在尝试测量一些代码的运行时间。首先我使用了一个计时装饰器:

#!/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.)

产生结果

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

这里我使用 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

使用 timeit 测试结果基本相同,但是使用 timing 装饰器时,time_indexingtime_izip 更快。

这种差异是由什么造成的?

哪种方法应该被信任?

如果是这样,那么哪一个呢?


2
顺便提一下,对于方法而言,func_name 属性并不总是可靠的,只适用于函数。因此,最好使用 __name__。可以尝试使用 time.sleep 进行测试。 - Asclepius
@A-B-B:感谢您的纠正。 - unutbu
9个回答

161
使用functools中的包装器来改进Matt Alcock的答案。
from functools import wraps
from time import time

def timing(f):
    @wraps(f)
    def wrap(*args, **kw):
        ts = time()
        result = f(*args, **kw)
        te = time()
        print('func:%r args:[%r, %r] took: %2.4f sec' % \
          (f.__name__, args, kw, te-ts))
        return result
    return wrap

在一个例子中:
@timing
def f(a):
    for _ in range(a):
        i = 0
    return -1

调用被 @timing 包装的方法 f

func:'f' args:[(100000000,), {}] took: 14.2240 sec
f(100000000)

这样做的优点是可以保留原始函数的属性;也就是说,返回的函数能够正确地保留函数名称和文档字符串等元数据。

5
我不理解"wraps"在这里添加了什么额外的功能。您能详细说明一下吗? - TheRealFakeNews
19
wraps将内部函数的元数据复制到外层函数。没有它,修饰后的函数对象将引用包装器而不是内部函数。这仅在使用反射工具(例如调试器)时才会成为问题。例如,如果我们在没有 wraps 的情况下调用修饰的函数的 help,则帮助信息将显示装饰器而不是内部函数。 - Thang
7
@skjerns,我认为你不能假设计时装饰器不会成为任何生产代码的一部分。在生产过程中记录仪表数据肯定是一件事情。既然遵循这个最佳实践并没有任何负面影响,那么使用 wraps 作为默认值可能是最好的选择。 - Dustin Wyatt
9
如果您使用的是Python 3.6或更高版本,您可以将print替换为类似于print(f'Function {f.__name__} took {te-ts:2.4f} seconds')的内容。 - kotchwane
1
太好了,这正是我在寻找的,谢谢! - jacktrader
显示剩余2条评论

52
我会使用计时装饰器,因为你可以使用注释在代码中添加计时,而不是用计时逻辑弄乱代码。
import time

def timeit(f):

    def timed(*args, **kw):

        ts = time.time()
        result = f(*args, **kw)
        te = time.time()

        print 'func:%r args:[%r, %r] took: %2.4f sec' % \
          (f.__name__, args, kw, te-ts)
        return result

    return timed

使用装饰器很容易,只需使用注释即可。

@timeit
def compute_magic(n):
     #function definition
     #....

或者重新给你想计时的函数取一个别名。
compute_magic = timeit(compute_magic)

12
我认为在这里使用 functools.wraps 会稍微有所改善。 - kuzzooroo
2
出于好奇,这个答案是从这里复制的吗?:https://www.andreas-jung.com/contents/a-python-decorator-for-measuring-the-execution-time-of-methods - emschorsch
我认为在Stackoverflow上引用不同位置的代码是完全可以的。我没有看到任何问题 @emschorsch - London guy

25

使用timeit。多次运行测试可以获得更好的结果。

func_list=[locals()[key] for key in locals().keys() 
           if callable(locals()[key]) and key.startswith('time')]

alist=range(1000000)
times=[]
for f in func_list:
    n = 10
    times.append( min(  t for t,_,_ in (f(alist,31) for i in range(n)))) 

for (time,func_name) in zip(times, func_list):
    print '%s took %0.3fms.' % (func_name, time*1000.)

->

<function wrapper at 0x01FCB5F0> took 39.000ms.
<function wrapper at 0x01FCB670> took 41.000ms.

是的,那似乎是原因。谢谢! - unutbu
46
顺便提一下,timeit在测试期间还会禁用垃圾回收,这可能是另一个需要注意的事项。 - Charles Merriam

8

受Micah Smith的回答启发,我改用了funcy来直接打印(而非使用日志模块)。

下面适用于在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)

6

我厌倦了使用from __main__ import foo,现在使用这个方法——对于简单的参数,其中%r有效,并且不在Ipython中使用。
(为什么timeit只能在字符串上工作,而不能在thunks / closures即timefunc(f, arbitrary args)上工作?)


import timeit

def timef( funcname, *args, **kwargs ):
    """ timeit a func with args, e.g.
            for window in ( 3, 31, 63, 127, 255 ):
                timef( "filter", window, 0 )
    This doesn't work in ipython;
    see Martelli, "ipython plays weird tricks with __main__" in Stackoverflow        
    """
    argstr = ", ".join([ "%r" % a for a in args]) if args  else ""
    kwargstr = ", ".join([ "%s=%r" % (k,v) for k,v in kwargs.items()]) \
        if kwargs  else ""
    comma = ", " if (argstr and kwargstr)  else ""
    fargs = "%s(%s%s%s)" % (funcname, argstr, comma, kwargstr)
        # print "test timef:", fargs
    t = timeit.Timer( fargs, "from __main__ import %s" % funcname )
    ntime = 3
    print "%.0f usec %s" % (t.timeit( ntime ) * 1e6 / ntime, fargs)

#...............................................................................
if __name__ == "__main__":
    def f( *args, **kwargs ):
        pass

    try:
        from __main__ import f
    except:
        print "ipython plays weird tricks with __main__, timef won't work"
    timef( "f")
    timef( "f", 1 )
    timef( "f", """ a b """ )
    timef( "f", 1, 2 )
    timef( "f", x=3 )
    timef( "f", x=3 )
    timef( "f", 1, 2, x=3, y=4 )

新增:参见“ipython对main有奇怪的把戏”,Martelli在通过ipython运行doctest中讨论。


谢谢!这肯定会让将函数放入timeit更容易。如果您使用fargs ='%s(*%s,**%s)'%(funcname,args,kwargs),则可以省略argstrkwargstrcomma,但也许这会使fargs难以阅读一些。 - unutbu

4
这是一种需要的类型,你希望一个库提供一个便携式的解决方案--DRY(Don't Repeat Yourself)。幸运的是,funcy.log_durations 可以提供答案。
文档中的示例:
@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)
# ...

请浏览funcy文档以获取其他变体,例如不同的关键字参数和 @log_iter_durations


2
只是猜测,可能差异在于range()值的数量级差异?
从你的原始来源:
alist=range(1000000)

从你的timeit例子:

alist=range(100000)

就算可能没有多大价值,这里是我在将范围设为一百万时所得到的结果:

$ python -V
Python 2.6.4rc2

$ 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: 69.6 msec per loop

$ python -m timeit -s '' 'alist=range(1000000);[alist[i:i+31] for i in range(0, len(alist), 31)]'
10 loops, best of 3: 67.6 msec per loop

由于我在我的系统上无法导入“decorator”模块,所以我无法运行您的其他代码。


更新 - 当我在没有涉及装饰器的情况下运行您的代码时,我发现与您一样存在差异。

$ ./test.py
time_indexing took 84.846ms.
time_izip took 132.574ms.

感谢您发布这个问题,我今天学到了新的东西。=)

我已经移除了装饰器模块,这样我的代码更容易运行。你能试一下吗? 当你运行脚本时,你是否看到明显的速度差异? 另外,我将范围从10^5更改为10^6,以便比较更加公平。 谢谢。 - unutbu
已更新,就算不值得一提,但貌似你现在得到了答案。没问题。 - mpontillo

1

无论这个特定的练习如何,我想使用timeit是更安全可靠的选择。它也是跨平台的,而不像你的解决方案。


这个有什么不跨平台的地方吗? - skjerns

0
这是一个适用于异步和同步函数的装饰器,它会打印出漂亮易读的输出,例如8微秒、200毫秒等等...
import asyncio
import time
from typing import Callable, Any

def timed(fn: Callable[..., Any]) -> Callable[..., Any]:
    """
    Decorator log test start and end time of a function

    :param fn: Function to decorate
    :return: Decorated function

    Example:
    >>> @timed
    >>> def test_fn():
    >>>     time.sleep(1)
    >>> test_fn()

    """

    def wrapped_fn(*args: Any, **kwargs: Any) -> Any:
        start = time.time()
        print(f'Running {fn.__name__}...')
        ret = fn(*args, **kwargs)
        duration_str = get_duration_str(start)
        print(f'Finished {fn.__name__} in {duration_str}')
        return ret

    async def wrapped_fn_async(*args: Any, **kwargs: Any) -> Any:
        start = time.time()
        print(f'Running {fn.__name__}...')
        ret = await fn(*args, **kwargs)
        duration_str = get_duration_str(start)
        print(f'Finished {fn.__name__} in {duration_str}')
        return ret

    if asyncio.iscoroutinefunction(fn):
        return wrapped_fn_async
    else:
        return wrapped_fn
    
    
def get_duration_str(start: float) -> str:
    """Get human readable duration string from start time"""
    duration = time.time() - start
    if duration > 1:
        duration_str = f'{duration:,.3f}s'
    elif duration > 1e-3:
        duration_str = f'{round(duration * 1e3)}ms'
    elif duration > 1e-6:
        duration_str = f'{round(duration * 1e6)}us'
    else:
        duration_str = f'{duration * 1e9}ns'
    return duration_str

这里有一个与之相同的gist

网页内容由stack overflow 提供, 点击上面的
可以查看英文原文,
原文链接