timeit 和它的 default_timer 完全不同意 [英] timeit and its default_timer completely disagree

问题描述

我对这两个函数进行了基准测试(它们将配对解压缩回源列表，来自此处):

I benchmarked these two functions (they unzip pairs back into source lists, came from here):

n = 10**7
a = list(range(n))
b = list(range(n))
pairs = list(zip(a, b))

def f1(a, b, pairs):
    a[:], b[:] = zip(*pairs)

def f2(a, b, pairs):
    for i, (a[i], b[i]) in enumerate(pairs):
        pass

timeit.timeit 的结果(五轮，数字是秒):

Results with timeit.timeit (five rounds, numbers are seconds):

f1 1.06   f2 1.57   
f1 0.96   f2 1.69   
f1 1.00   f2 1.85   
f1 1.11   f2 1.64   
f1 0.95   f2 1.63   

很明显f1比f2快很多，对吧?

So clearly f1 is a lot faster than f2, right?

但后来我也用 timeit.default_timer 进行了测量，得到了完全不同的图片:

But then I also measured with timeit.default_timer and got a completely different picture:

f1 7.28   f2 1.92   
f1 5.34   f2 1.66   
f1 6.46   f2 1.70   
f1 6.82   f2 1.59   
f1 5.88   f2 1.63   

很明显f2要快很多，对吧?

So clearly f2 is a lot faster, right?

叹气.为什么计时完全不同，我应该相信哪种计时方法?

Sigh. Why do the timings totally differ like that, and which timing method should I believe?

完整的基准代码:

from timeit import timeit, default_timer

n = 10**7
a = list(range(n))
b = list(range(n))
pairs = list(zip(a, b))

def f1(a, b, pairs):
    a[:], b[:] = zip(*pairs)

def f2(a, b, pairs):
    for i, (a[i], b[i]) in enumerate(pairs):
        pass

print('timeit')
for _ in range(5):
    for f in f1, f2:
        t = timeit(lambda: f(a, b, pairs), number=1)
        print(f.__name__, '%.2f' % t, end='   ')
    print()

print('default_timer')
for _ in range(5):
    for f in f1, f2:
        t0 = default_timer()
        f(a, b, pairs)
        t = default_timer() - t0
        print(f.__name__, '%.2f' % t, end='   ')
    print()

推荐答案

正如 Martijn 所评论的，区别在于 Python 的垃圾收集，timeit.timeit 在其运行期间禁用.而 zip 创建了 10 万个迭代器对象，给定的 1000 万个可迭代对象中的每一个对应一个对象.

As Martijn commented, the difference is Python's garbage collection, which timeit.timeit disables during its run. And zip creates 10 million iterator objects, one for each of the 10 million iterables it's given.

所以，垃圾收集 1000 万个对象需要很多时间，对吧?谜底解开！

So, garbage-collecting 10 million objects simply takes a lot of time, right? Mystery solved!

嗯……不.这并不是真正发生的事情，而且比这更有趣.并且要在现实生活中更快地编写此类代码，需要吸取教训.

Well... no. That's not really what happens, and it's way more interesting than that. And there's a lesson to be learned to make such code faster in real life.

Python 丢弃不再需要的对象的主要方法是引用计数.垃圾收集器在这里被禁用，用于引用cycles，引用计数不会捕获它.并且这里没有任何循环，所以它都被引用计数丢弃了，垃圾收集器实际上并没有收集任何垃圾.

Python's main way to discard objects no longer needed is reference counting. The garbage collector, which is being disabled here, is for reference cycles, which the reference counting won't catch. And there aren't any cycles here, so it's all discarded by reference counting and the garbage collector doesn't actually collect any garbage.

让我们看看一些事情.首先，让我们通过自己禁用垃圾收集器来重现更快的时间.

Let's look at a few things. First, let's reproduce the much faster time by disabling the garbage collector ourselves.

通用设置代码(所有其他代码块应在此之后直接运行在新运行中，不要组合它们):

Common setup code (all further blocks of code should be run directly after this in a fresh run, don't combine them):

import gc
from timeit import default_timer as timer

n = 10**7
a = list(range(n))
b = list(range(n))
pairs = list(zip(a, b))

垃圾收集计时启用(默认):

Timing with garbage collection enabled (the default):

t0 = timer()
a[:], b[:] = zip(*pairs)
t1 = timer()
print(t1 - t0)

我跑了 3 次，分别用了 7.09、7.03 和 7.09 秒.

I ran it three times, took 7.09, 7.03 and 7.09 seconds.

垃圾收集计时禁用:

t0 = timer()
gc.disable()
a[:], b[:] = zip(*pairs)
gc.enable()
t1 = timer()
print(t1 - t0)

耗时 0.96、1.02 和 0.99 秒.

Took 0.96, 1.02 and 0.99 seconds.

所以现在我们知道确实是垃圾收集以某种方式占用了大部分时间，即使它没有收集任何东西.

So now we know it's indeed the garbage collection that somehow takes most of the time, even though it's not collecting anything.

这里有一些有趣的事情:大部分时间已经zip迭代器的创建负责:

Here's something interesting: Already just the creation of the zip iterator is responsible for most of the time:

t0 = timer()
z = zip(*pairs)
t1 = timer()
print(t1 - t0)

这花了 6.52、6.51 和 6.50 秒.

That took 6.52, 6.51 and 6.50 seconds.

请注意，我将 zip 迭代器保存在一个变量中，因此甚至没有任何东西可以丢弃，无论是通过引用计数还是通过垃圾收集！

Note that I kept the zip iterator in a variable, so there isn't even anything to discard yet, neither by reference counting nor by garbage collecting!

什么?！那么时间都去哪儿了?

What?! Where does the time go, then?

嗯...正如我所说，没有引用循环，所以垃圾收集器实际上不会收集任何垃圾.但是垃圾收集器不知道！为了弄清楚，它需要检查！

Well... as I said, there are no reference cycles, so the garbage collector won't actually collect any garbage. But the garbage collector doesn't know that! In order to figure that out, it needs to check!

由于迭代器可以成为引用循环的一部分，它们被注册用于垃圾收集跟踪.让我们看看有多少对象由于 zip 创建而被跟踪(在通用设置代码之后执行此操作):

Since the iterators could become part of a reference cycle, they're registered for garbage collection tracking. Let's see how many more objects get tracked due to the zip creation (doing this just after the common setup code):

gc.collect()
tracked_before = len(gc.get_objects())
z = zip(*pairs)
print(len(gc.get_objects()) - tracked_before)

输出:10000003 跟踪的新对象.我相信这是 zip 对象本身，它的内部元组保存迭代器，它的内部 result holder 元组，以及 1000 万个迭代器.

The output: 10000003 new objects tracked. I believe that's the zip object itself, its internal tuple to hold the iterators, its internal result holder tuple, and the 10 million iterators.

好的，垃圾收集器跟踪所有这些对象.但是，这是什么意思?好吧，每隔一段时间，在创建一定数量的新对象之后，收集器就会检查跟踪的对象，看看是否有一些是垃圾并且可以丢弃.收集器保持三个世代"跟踪的对象.新对象进入第 0 代.如果它们在那里的集合运行中幸存下来，它们将被移到第 1 代.如果它们在那里的一个集合中幸存下来，它们将被移到第 2 代.如果它们在那里的进一步收集运行中幸存下来，它们将留在第 1 代2.我们来看看前后几代:

Ok, so the garbage collector tracks all these objects. But what does that mean? Well, every now and then, after a certain number of new object creations, the collector goes through the tracked objects to see whether some are garbage and can be discarded. The collector keeps three "generations" of tracked objects. New objects go into generation 0. If they survive a collection run there, they're moved into generation 1. If they survive a collection there, they're moved into generation 2. If they survive further collection runs there, they remain in generation 2. Let's check the generations before and after:

gc.collect()
print('collections:', [stats['collections'] for stats in gc.get_stats()])
print('objects:', [len(gc.get_objects(i)) for i in range(3)])
z = zip(*pairs)
print('collections:', [stats['collections'] for stats in gc.get_stats()])
print('objects:', [len(gc.get_objects(i)) for i in range(3)])

输出(每行显示三代的值):

Output (each line shows values for the three generations):

collections: [13111, 1191, 2]
objects: [17, 0, 13540]
collections: [26171, 2378, 20]
objects: [317, 2103, 10011140]

10011140 显示 1000 万个迭代器中的大多数不仅注册用于跟踪，而且已经在第 2 代中.因此它们至少是两次垃圾收集运行的一部分.第 2 代收集的数量从 2 次增加到 20 次，因此我们的数百万个迭代器参与了多达 20 次垃圾收集运行(2 次进入第 2 代，而在第 2 代中则多达 18 次).我们还可以注册一个回调来更精确地计数:

The 10011140 shows that most of the 10 million iterators were not just registered for tracking, but are already in generation 2. So they were part of at least two garbage collection runs. And the number of generation 2 collections went up from 2 to 20, so our millions of iterators were part of up to 20 garbage collection runs (two to get into generation 2, and up to 18 more while already in generation 2). We can also register a callback to count more precisely:

checks = 0
def count(phase, info):
    if phase == 'start':
        global checks
        checks += len(gc.get_objects(info['generation']))

gc.callbacks.append(count)
z = zip(*pairs)
gc.callbacks.remove(count)
print(checks)

这告诉我总共有 63,891,314 次检查(即平均每个迭代器是超过 6 次垃圾收集运行的一部分).这是很多工作.所有这一切只是为了在使用它之前创建 zip 迭代器.

That told me 63,891,314 checks total (i.e., on average, each iterator was part of over 6 garbage collection runs). That's a lot of work. And all this just to create the zip iterator, before even using it.

同时，循环

for i, (a[i], b[i]) in enumerate(pairs):
    pass

几乎不创建任何新对象.让我们检查跟踪 enumerate 有多少原因:

creates almost no new objects at all. Let's check how much tracking enumerate causes:

gc.collect()
tracked_before = len(gc.get_objects())
e = enumerate(pairs)
print(len(gc.get_objects()) - tracked_before)

输出:3 个跟踪的新对象(enumerate 迭代器对象本身，它为迭代pairs 而创建的单个迭代器，以及结果它将使用的元组(代码此处)).

Output: 3 new objects tracked (the enumerate iterator object itself, the single iterator it creates for iterating over pairs, and the result tuple it'll use (code here)).

我会说这回答了为什么时间完全不同?".zip 解决方案创建了数百万个经过多次垃圾收集运行的对象，而循环解决方案则不然.所以禁用垃圾收集器极大地帮助了 zip 解决方案，而循环解决方案并不关心.

I'd say that answers the question "Why do the timings totally differ like that?". The zip solution creates millions of objects that go through multiple garbage collection runs, while the loop solution doesn't. So disabling the garbage collector helps the zip solution tremendously, while the loop solution doesn't care.

现在关于第二个问题:我应该相信哪种计时方法?".以下是文档对此的说明(强调我的):

Now about the second question: "Which timing method should I believe?". Here's what the documentation has to say about it (emphasis mine):

默认情况下，timeit() 在计时期间暂时关闭垃圾收集.这种方法的优点是它使独立时序更具可比性.缺点是GC 可能是被测量函数性能的重要组成部分.如果是这样，GC 可以作为设置字符串中的第一个语句重新启用.例如:

By default, timeit() temporarily turns off garbage collection during the timing. The advantage of this approach is that it makes independent timings more comparable. The disadvantage is that GC may be an important component of the performance of the function being measured. If so, GC can be re-enabled as the first statement in the setup string. For example:

timeit.Timer('for i in range(10): oct(i)', 'gc.enable()').timeit()

在我们这里的例子中，垃圾收集的成本并不是来自其他一些不相关的代码.它直接由 zip 调用引起.当你运行它时，你确实付出了这个代价.因此，在这种情况下，我确实认为它是被测量功能性能的重要组成部分".直接回答问题:这里我相信 default_timer 方法，而不是 timeit 方法.或者换一种说法:这里应该使用 timeit 方法并按照文档中的建议启用垃圾收集.

In our case here, the cost of garbage collection doesn't stem from some other unrelated code. It's directly caused by the zip call. And you do pay this price in reality, when you run that. So in this case, I do consider it an "important component of the performance of the function being measured". To directly answer the question as asked: Here I'd believe the default_timer method, not the timeit method. Or put differently: Here the timeit method should be used with enabling garbage collection as suggested in the documentatiion.

或者……或者，我们实际上可以禁用垃圾收集作为解决方案的一部分(不仅仅是为了进行基准测试):

Or... alternatively, we could actually disable garbage collection as part of the solution (not just for benchmarking):

def f1(a, b, pairs):
    gc.disable()
    a[:], b[:] = zip(*pairs)
    gc.enable()

但这是个好主意吗?以下是 gc 文档 所说的:

But is that a good idea? Here's what the gc documentation says:

由于收集器补充了 Python 中已经使用的引用计数，如果您确定您的程序不会创建引用循环，您可以禁用收集器.

Since the collector supplements the reference counting already used in Python, you can disable the collector if you are sure your program does not create reference cycles.

听起来是件好事.但我不确定我不会在我的程序的其他地方创建引用循环，所以我用 gc.enable() 完成以在我完成后重新打开垃圾收集.此时，由于引用计数，所有这些临时对象都已被丢弃.所以我所做的就是避免大量无意义的垃圾收集检查.我发现这是一个宝贵的教训，如果我知道我只是暂时创建了很多对象，我将来可能会这样做.

Sounds like it's an ok thing to do. But I'm not sure I don't create reference cycles elsewhere in my program, so I finish with gc.enable() to turn garbage collection back on after I'm done. At that point, all those temporary objects have already been discarded thanks to reference counting. So all I'm doing is avoiding lots of pointless garbage collection checks. I find this a valuable lesson and I might actually do that in the future, if I know I only temporarily create a lot of objects.

最后，我强烈建议您阅读 gc 模块文档 和 Python 开发人员指南中的 CPython 垃圾收集器的设计.大部分内容都很容易理解，我觉得很有趣，也很有启发性.

Finally, I highly recommend reading the gc module documentation and the Design of CPython’s Garbage Collector in Python's developer guide. Most of it is easy to understand, and I found it quite interesting and enlightening.

这篇关于timeit 和它的 default_timer 完全不同意的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！