seltsames Ergebnis von Timeit

Question

Ich habe versucht, die Funktionalität von IPython% Zeit zu wiederholen, aber aus irgendeinem seltsamen Grund sind die Ergebnisse des Testens einiger Funktionen entsetzlich.

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) 

und seine Ausgabe:

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

Wie Sie in Python sehen können, habe ich 100 Schleifen statt 10000 (und erhalten 35000 mal langsamer Ergebnis) wie in ipython, weil es wirklich lange dauert. Kann jemand erklären, warum das Ergebnis in Python so langsam ist?

UPD: Hier ist cProfile.run('my_timeit(code=np_code, setup=np_setup, rep=3, loops=10000)') Ausgang:

  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

Nun, ein Problem ist, dass Sie die Ergebnisse falsch interpretieren. ipython sagt Ihnen, wie lange jede der 10.000 Iterationen für den Satz von 10.000 Iterationen mit der niedrigsten Gesamtzeit dauerte. Das Modul timeit.repeat berichtet, wie lange die gesamte Runde von 100 Iterationen dauerte (wiederum für die kürzeste von drei). Die wahre Diskrepanz ist also 46,1 μs pro Schleife (ipython) gegenüber 16,5 ms pro Schleife (Python), immer noch ein Faktor von ~ 350x Unterschied, aber nicht 35.000x.

Sie haben keine Profilergebnisse für ipython angezeigt. Ist es möglich, dass Sie in Ihrer ipython Sitzung entweder from numpy import sum oder from numpy import * haben? Wenn ja, würden Sie die numpy.sum timing (die für numpy Arrays optimiert ist und run several orders of magnitude faster), während Ihre python Code (die die Globals in einer Weise isoliert, die ipython nicht tut) lief die normale sum (die alle konvertieren muss die Werte zu Python int s und summieren sie).

Wenn Sie Ihre Profiling-Ausgabe überprüfen, wird praktisch die gesamte Arbeit in sum erledigt; Wenn dieser Teil Ihres Codes um mehrere Größenordnungen beschleunigt wurde, würde sich die Gesamtzeit ähnlich verringern. Das würde die "echte" Diskrepanz erklären; in dem oben verlinkten Testfall war es ein 40x Unterschied, und das war für ein kleineres Array (je kleiner das Array, desto weniger kann numpy "zeigen") mit komplexeren Werten (vs Summierung von 0s und 1s hier glaube ich) .

Der Rest (falls vorhanden) ist wahrscheinlich eine Frage, wie der Code eval ed etwas anders, oder möglicherweise Seltsamkeit mit dem random shuffle (für konsistente Tests wird, würden Sie random mit einem konsistenten Samen säen machen wollen die "Zufälligkeit" wiederholbar), aber ich bezweifle, dass das ein Unterschied von mehr als ein paar Prozent ist.

Answer 2

Es könnte dieser Code eine Reihe von Gründen langsamer sein als ein anderer in einer Implementierung von Python läuft. Einer kann anders als ein anderer optimiert werden, man kann bestimmte Teile vorkompilieren, während der andere vollständig interpretiert wird. Die einzige Möglichkeit, herauszufinden, warum, besteht darin, Ihren Code zu profilieren.

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

import cProfile 

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

Wird ein ähnliches Ergebnis wie

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} 

geben Welche Sie zeigt an, wenn Funktionsaufrufe gemacht wurden, wie oft sie und gemacht wurden, wie lange sie dauerte.