timeit的奇怪结果

Question

我试着重复IPython％time的功能，但出于某种奇怪的原因，某些函数的测试结果是可怕的。

IPython的：

In [11]: from random import shuffle 
    ....: import numpy as np 
    ....: def numpy_seq_el_rank(seq, el): 
    ....:  return sum(seq < el) 
    ....: 
    ....: seq = np.array(xrange(10000)) 
    ....: shuffle(seq) 
    ....: 

In [12]: %timeit numpy_seq_el_rank(seq, 10000//2) 
10000 loops, best of 3: 46.1 µs per loop 

的Python：

from timeit import timeit, repeat 

def my_timeit(code, setup, rep, loops): 
    result = repeat(code, setup=setup, repeat=rep, number=loops) 
    return '%d loops, best of %d: %0.9f sec per loop'%(loops, rep, min(result)) 

np_setup = ''' 
from random import shuffle 
import numpy as np 
def numpy_seq_el_rank(seq, el): 
    return sum(seq < el) 

seq = np.array(xrange(10000)) 
shuffle(seq) 
''' 
np_code = 'numpy_seq_el_rank(seq, 10000//2)' 

print 'Numpy seq_el_rank:\n\t%s'%my_timeit(code=np_code, setup=np_setup, rep=3, loops=100) 

，其输出：

Numpy seq_el_rank: 
    100 loops, best of 3: 1.655324947 sec per loop 

正如你所看到的，在Python我做了100圈，而不是10000（并获得比ipython慢​​35000倍，结果），因为它需要很长时间。任何人都可以解释为什么python的结果如此之慢？

UPD： 这里是cProfile.run('my_timeit(code=np_code, setup=np_setup, rep=3, loops=10000)')输出：

  30650 function calls in 4.987 seconds 

    Ordered by: standard name 

    ncalls tottime percall cumtime percall filename:lineno(function) 
     1 0.000 0.000 4.987 4.987 <string>:1(<module>) 
     1 0.000 0.000 0.000 0.000 <timeit-src>:2(<module>) 
     3 0.001 0.000 4.985 1.662 <timeit-src>:2(inner) 
     300 0.006 0.000 4.961 0.017 <timeit-src>:7(numpy_seq_el_rank) 
     1 0.000 0.000 4.987 4.987 Lab10.py:47(my_timeit) 
     3 0.019 0.006 0.021 0.007 random.py:277(shuffle) 
     1 0.000 0.000 0.002 0.002 timeit.py:121(__init__) 
     3 0.000 0.000 4.985 1.662 timeit.py:185(timeit) 
     1 0.000 0.000 4.985 4.985 timeit.py:208(repeat) 
     1 0.000 0.000 4.987 4.987 timeit.py:239(repeat) 
     2 0.000 0.000 0.000 0.000 timeit.py:90(reindent) 
     3 0.002 0.001 0.002 0.001 {compile} 
     3 0.000 0.000 0.000 0.000 {gc.disable} 
     3 0.000 0.000 0.000 0.000 {gc.enable} 
     3 0.000 0.000 0.000 0.000 {gc.isenabled} 
     1 0.000 0.000 0.000 0.000 {globals} 
     3 0.000 0.000 0.000 0.000 {isinstance} 
     3 0.000 0.000 0.000 0.000 {len} 
     3 0.000 0.000 0.000 0.000 {method 'append' of 'list' objects} 
     1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects} 
    29997 0.001 0.000 0.001 0.000 {method 'random' of '_random.Random' objects} 
     2 0.000 0.000 0.000 0.000 {method 'replace' of 'str' objects} 
     1 0.000 0.000 0.000 0.000 {min} 
     3 0.003 0.001 0.003 0.001 {numpy.core.multiarray.array} 
     1 0.000 0.000 0.000 0.000 {range} 
     300 4.955 0.017 4.955 0.017 {sum} 
     6 0.000 0.000 0.000 0.000 {time.clock} 

Answer 1

那么，一个问题是你误读结果。 ipython告诉你10,000次迭代的总次数最少的10,000次迭代需要多长时间。 timeit.repeat模块报告整个100次迭代花费了多长时间（再次，最短的三次）。所以真正的差异是每循环46.1μs（ipython）与每循环16.5ms（python），仍然是差异的约350倍，但不是35,000x。

您没有显示ipython的分析结果。是否有可能在ipython会话中，您执行了from numpy import sum或from numpy import *？如果是这样的话，你应该已经计算了numpy.sum（它对numpy阵列进行了优化，将run several orders of magnitude faster），而你的python代码（它以ipython没有的方式隔离了全局变量）运行了正常的sum（它必须将所有Python int的值并将它们相加）。

如果您检查您的分析输出，几乎所有的工作都在sum;如果你的代码部分被加速了几个数量级，那么总的时间会相应地减少。这将解释“真实”的差异;在上面链接的测试案例中，它是一个40倍的差异，这是一个更小的阵列（阵列越小，numpy可以炫耀的越少），具有更复杂的值（我相信在这里总结0和1） 。

其余部分（如果有的话）可能是代码是如何被eval版略有不同，或可能与random洗牌（为一致的测试古怪的问题，你会想种子random具有一致的种子，使“随机性”是可重复的），但我怀疑这个差距超过百分之几。

Answer 2

有可能是任何数量的这段代码是一个Python实现比其他的运行速度较慢的原因。一个可能比另一个更优化，可以预先编译某些部分，而另一个完全解释。找出原因的唯一方法是分析您的代码。

https://docs.python.org/2/library/profile.html

import cProfile 

cProfile.run('repeat(code, setup=setup, repeat=rep, number=loops)') 

会给类似于

ncalls tottime percall cumtime percall filename:lineno(function) 
    1 0.000 0.000 0.000 0.000 <stdin>:1(testing) 
    1 0.000 0.000 0.000 0.000 <string>:1(<module>) 
    1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects} 
    1 0.000 0.000 0.000 0.000 {method 'upper' of 'str' objects} 

因此这表明你在函数调用进行了改造，他们多少次制成，他们耗时多久。