Inconsistency between %time and %timeit in IPython

Question

I am confronted to a weird situation that I can't explain. Here is my test timing the generation of a large list of tuples:

In [1]: def get_list_of_tuples():
   ...:     return [(i,) for i in range(10**6)]
   ...:

In [2]: %time res = get_list_of_tuples()
CPU times: user 0.93 s, sys: 0.08 s, total: 1.01 s
Wall time: 0.98 s

In [3]: %timeit res = get_list_of_tuples()
1 loops, best of 3: 92.1 ms per loop

As you can see, the generation of this large list of tuples takes just below a second. timeit reports the execution time to be around 0.1 second. Why is there such a big difference in the two reports?

(Tested on IPython 0.11, Python 2.6.5.)

Roberson

Do you get the same result if you run %timeit first and %time second? – Geosphere

Interesting comment. Yes, I get similar results with a reversed order of execution. – Roberson

I don't know IronPython, so I can't say much about %time or %timeit, but my guess would be that %time repeats the timing test 10 times. – Telluride

I am not using IronPython, but IPython. Also %timeit is the function that executes the command several times, not %time. – Roberson

%timeit does a best of 3 runs, so what does: for i in range(3): %time res=get_list_of_tuples() get you? For this reason, it is normal for %timeit to report smaller numbers (I typically see ~2x), but 10x is a lot. I don't suppose you are on Windows? – Coloratura

I tested this code on Linux (CentOS 5 and 6, Ubuntu, Mac OS X) and get similar results on all OS. Running %time several does not change the results. – Roberson

Answer 1

The main difference is because "by default, timeit() temporarily turns off garbage collection during the timing".

Turning the garbage collection returns results similar to the one shown in the question, i.e. the time of execution with garbage collection is magnitude bigger than the one without:

In [1]: import timeit

# Garbage collection on.
In [2]: N = 10; timeit.timeit('[(i,) for i in range(10**6)]', 'gc.enable()', number=N) / N
Out[2]: 0.74884700775146484
# 749 ms per loop.

# Garbage collection off.
In [3]: N = 10; timeit.timeit('[(i,) for i in range(10**6)]', number=N) / N
Out[3]: 0.15906109809875488
# 159 ms per loop.

Roberson

Answer 2

Benoit,

If I use Python 2.6.6 and IPython 0.10 then I see similar answers to yours. Using Python 2.7.1 and IPython 0.10.1 I get something more sensible:

% ipython
Python 2.7.1 (r271:86832, Nov  3 2011, 16:23:57) 
Type "copyright", "credits" or "license" for more information.

IPython 0.10.1 -- An enhanced Interactive Python.

In [1]: def get_list_of_tuples():
   ...:     return [(i,) for i in range(10**6)]
   ...: 

In [2]: %time res = get_list_of_tuples()
CPU times: user 0.25 s, sys: 0.10 s, total: 0.35 s
Wall time: 0.35 s

In [3]: %timeit res = get_list_of_tuples()
1 loops, best of 3: 215 ms per loop

Synaeresis

Got very similar results with IPython 0.11 and Python 2.7.2. – Roberson

Answer 3

%time - runs statement only once, and have measurement error

%timeit - runs statement few times, and choses most accurate time.

See Python timeit module documentation for some explanations

Charley

"RTFM" is not an answer to my question. If I generate a list of 10 million tuples instead of 1 million, %time reports 56 s and %timeit reports 882 ms. This is not normal and I want to know why. – Roberson

@badzil, have you tried to execute %time few times by hand? Are results the same? And if you have both 2.6 and 2.7 try to disassemble and find differences between generated codes (i have only 2.7) – Charley

The results are consistent if I run %time and %timeit several times. Can you elaborate on the generated code? – Roberson

@badzil, I can't reproduce your strange results. About generated code, i mean import dis; dis.dis(generate_list_of_tuples). Python 2.6 generates few extra insturctions code at pastebin, but this shouldn't affect time so much. I honestly do not know the reason for this inconsistency, maybe it's somehow related to garbage collector in 2.6, but it's just a guess. – Charley