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} 

因此這表明你在函數調用進行了改造，他們多少次製成，他們耗時多久。