28

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.)

badzil
  • 3,440
  • 4
  • 19
  • 27
  • 1
    Do you get the same result if you run %timeit first and %time second? – sth Dec 23 '11 at 18:01
  • 1
    Interesting comment. Yes, I get similar results with a reversed order of execution. – badzil Dec 23 '11 at 18:04
  • 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. – Tim Pietzcker Dec 23 '11 at 18:14
  • 2
    I am not using [IronPython](http://ironpython.codeplex.com/), but [IPython](http://ipython.org/). Also %timeit is the function that executes the command several times, not %time. – badzil Dec 23 '11 at 18:37
  • %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? – minrk Dec 24 '11 at 00:44
  • 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. – badzil Dec 24 '11 at 15:03

3 Answers3

43

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.
badzil
  • 3,440
  • 4
  • 19
  • 27
3

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
Doug Burke
  • 31
  • 1
-5

%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

reclosedev
  • 9,352
  • 34
  • 51
  • 5
    "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. – badzil Dec 23 '11 at 19:33
  • @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) – reclosedev Dec 23 '11 at 19:51
  • The results are consistent if I run %time and %timeit several times. Can you elaborate on the generated code? – badzil Dec 24 '11 at 15:02
  • @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](http://pastebin.com/nxFYrKpA), 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. – reclosedev Dec 24 '11 at 17:21