timeitの奇妙な結果

Question

私はIPython％の機能を繰り返してみましたが、いくつかの奇妙な理由のために、いくつかの機能のテスト結果は恐ろしいものです。

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（と取得35000倍遅い結果）は、実際には時間がかかるため、ipythonの場合と同じです。誰でもなぜPythonの結果がとても遅いのか説明できますか？

UPD：このコードは別のものよりパイソンの一の実装で遅く実行されている任意の数の理由があるかもしれません

  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回の反復がどれぐらいかかったかを報告しています（再び、最短3回）。したがって、実際の不一致は、ループ（ipython）あたり46.1μs対ループ（Python）あたり16.5msであり、依然として約350xの差ですが、35,000xではありません。

ipythonのプロファイリング結果が表示されませんでした。 ipythonセッションでfrom numpy import sumまたはfrom numpy import *のいずれかを実行した可能性はありますか？そうであれば、pythonコード（ipythonが含まれないようにグローバルを隔離したコード）が通常のsum（すべてを変換しなければならない）の間にnumpy.sum（これはnumpyアレイ用に最適化されており、run several orders of magnitude faster）値をPython int sに加えて合計します）。

プロファイリング出力を確認すると、事実上すべての作業はsumで実行されています。あなたのコードのその部分が数オーダーのスピードでスピードアップした場合、合計時間も同様に減少します。それは "本当の"不一致を説明するでしょう。上にリンクされたテストケースでは、それは40xの差であり、それはより小さい配列（配列が小さいほど、より小さく複雑な値でnumpyが少なくなる）でした（ここでは0と1を加算しています） 。

残りは（もしあれば）、おそらくコードが若干異なるeval編であること、または一貫性のテストのためのrandomシャッフル（とおそらくおかしなされる方法の問題である、あなたが作るために一貫性のある種子でrandomをシードにしたいと思います「乱雑さ」は繰り返し可能ですが）、それは数パーセント以上の違いだとは思っていません。

Answer 2

： ここcProfile.run('my_timeit(code=np_code, setup=np_setup, rep=3, loops=10000)')出力されます。 1つは、別のものとは異なるように最適化することができ、ある部分をあらかじめコンパイルし、もう一方を完全に解釈することができる。なぜあなたのコードをプロファイルするのかを理解する唯一の方法です。

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} 

と同様の結果が得られます。