strange result from timeit
<p>I tried to repeat the functionality of IPython %time, but for some strange reason, results of testing of some function are horrific.</p>

<p>IPython:</p>

<pre><code>In [11]: from random import shuffle
   ....: import numpy as np
   ....: def numpy_seq_el_rank(seq, el):
   ....:     return sum(seq &lt; 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
</code></pre>

<p>Python:</p>

<pre><code>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 &lt; 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)
</code></pre>

<p>And its output:</p>

<pre class="lang-none prettyprint-override"><code>Numpy seq_el_rank:
    100 loops, best of 3: 1.655324947 sec per loop
</code></pre>

<p>As you can see, in python i made 100 loops instead 10000 (<em>and get 35000 times slower result</em>) as in ipython, because it takes really long time. Can anybody explain why result in python is so slow?</p>

<p>UPD:
Here is <code>cProfile.run('my_timeit(code=np_code, setup=np_setup, rep=3, loops=10000)')</code> output:</p>

<pre class="lang-none prettyprint-override"><code>         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 &lt;string&gt;:1(&lt;module&gt;)
        1    0.000    0.000    0.000    0.000 &lt;timeit-src&gt;:2(&lt;module&gt;)
        3    0.001    0.000    4.985    1.662 &lt;timeit-src&gt;:2(inner)
      300    0.006    0.000    4.961    0.017 &lt;timeit-src&gt;: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}
</code></pre>

<p>Well, one issue is that you're misreading the results. <code>ipython</code> is telling you how long it took each of the 10,000 iterations for the set of 10,000 iterations with the lowest total time. The <code>timeit.repeat</code> module is reporting how long the whole round of 100 iterations took (again, for the shortest of three). So the real discrepancy is 46.1 Âµs per loop (ipython) vs. 16.5 ms per loop (python), still a factor of ~350x difference, but not 35,000x.</p>

<p>You didn't show profiling results for <code>ipython</code>. Is it possible that in your <code>ipython</code> session, you did either <code>from numpy import sum</code> or <code>from numpy import *</code>? If so, you'd have been timing the <code>numpy.sum</code> (which is optimized for <code>numpy</code> arrays and would <a href="http://stackoverflow.com/a/10922744/364696">run several orders of magnitude faster</a>), while your <code>python</code> code (which isolated the globals in a way that <code>ipython</code> does not) ran the normal <code>sum</code> (that has to convert all the values to Python <code>int</code>s and sum them).</p>

<p>If you check your profiling output, virtually all of your work is being done in <code>sum</code>; if that part of your code was sped up by several orders of magnitude, the total time would reduce similarly. That would explain the "real" discrepancy; in the test case linked above, it was a 40x difference, and that was for a smaller array (the smaller the array, the less <code>numpy</code> can "show off") with more complex values (vs. summing 0s and 1s here I believe).</p>

<p>The remainder (if any) is probably an issue of how the code is being <code>eval</code>ed slightly differently, or possibly weirdness with the <code>random</code> shuffle (for consistent tests, you'd want to seed <code>random</code> with a consistent seed to make the "randomness" repeatable) but I doubt that's a difference of more than a few percent.</p>

python debugging time ipython