timeit.timeit and timeit.repeat give different answers

[Dan Christensen]

The test below is done with Python 2.4a1 compiled from source, but
the same thing happens with Debian's python2.3_2.3.4-2.

Python 2.4a1 (#1, Jul 11 2004, 12:20:32)
[GCC 3.3.4 (Debian)] on linux2
Type "help", "copyright", "credits" or "license" for more information.[0.042751073837280273]

The results are consistent if repeated, i.e. timeit always produces
about 0.056 and repeat always produces about 0.043.

It doesn't help to do:

for i in range(10):
print t.timeit()

vs.

print t.repeat(10)

The problem happens on both machines I've tested it on. One is a
desktop. No other jobs running.

With Python 2.3, the results are affected by the setting of the
PYTHONPATH environment variable. With it unset or set to an empty
directory /tmp/foo I get results like above. With it set to an empty
directory /tmp/python, I get results that agree with each other.

But with Python 2.4, all three settings give results that disagree.

If I use the ipython shell, things are even worse: the results
disagree by a factor of almost 2!

I've read timeit.py and can't see how this might happen.

Any thoughts?

Dan

 

[Dan Christensen]

Can anyone confirm whether this discrepancy happens with other
installations of python on other hardware/OS's? It's a bit
disconcerting.

Thanks,

Dan

The test below is done with Python 2.4a1 compiled from source, but
the same thing happens with Debian's python2.3_2.3.4-2.

Python 2.4a1 (#1, Jul 11 2004, 12:20:32)
[GCC 3.3.4 (Debian)] on linux2
Type "help", "copyright", "credits" or "license" for more information.[0.042751073837280273]

The results are consistent if repeated, i.e. timeit always produces
about 0.056 and repeat always produces about 0.043.

It doesn't help to do:

for i in range(10):
print t.timeit()

vs.

print t.repeat(10)

The problem happens on both machines I've tested it on. One is a
desktop. No other jobs running.

With Python 2.3, the results are affected by the setting of the
PYTHONPATH environment variable. With it unset or set to an empty
directory /tmp/foo I get results like above. With it set to an empty
directory /tmp/python, I get results that agree with each other.

But with Python 2.4, all three settings give results that disagree.

If I use the ipython shell, things are even worse: the results
disagree by a factor of almost 2!

I've read timeit.py and can't see how this might happen.

Any thoughts?

Dan

 

[Peter Otten]

Can anyone confirm whether this discrepancy happens with other
installations of python on other hardware/OS's? It's a bit
disconcerting.

Measured on an aging Suse 8.1:

Python 2.3.3 (#1, Jan 3 2004, 13:57:08)
[GCC 3.2] on linux2
Type "help", "copyright", "credits" or "license" for more informa
tion.

import timeit, time
t = timeit.Timer()
t.timeit() 0.054198980331420898
t.repeat(1) [0.053848981857299805]
t.timeit() 0.061758041381835938
t.repeat(1) [0.053132057189941406]
t.timeit() 0.055379867553710938
t.repeat(1) [0.074712038040161133]
tt = t.repeat(1000)
tt.sort()
tt[0] 0.053070068359375
tt[-1] 0.056523799896240234

And now what?

I'd just stick with the commandline's "best of N" strategy. Also, I would
expect the "pass" statement to be the fastest to execute and therefore the
least accurate to measure.

Peter

 

[Dan Christensen]

[lots of noisy data]

And now what?

I'd just stick with the commandline's "best of N" strategy.

As I tried to make clear, this isn't a question of noisy data. The
two functions produce roughly the same numbers as themselves, but are
consistently in disagreement. In more detail:

jdc@itchy:~$ unset PYTHONPATH
jdc@itchy:~$ python
Python 2.3.4 (#2, Jun 19 2004, 18:15:30)
[GCC 3.3.4 (Debian)] on linux2
Type "help", "copyright", "credits" or "license" for more information.
# A t.timeit group:
0.089442968368530273

# A t.repeat group:

t.repeat(1) [0.073434114456176758]
t.repeat(1) [0.073648929595947266]
t.repeat(1) [0.074430942535400391]
t.repeat(1) [0.07358098030090332]
t.repeat(1)

[0.073504924774169922]

# t.timeit in a for loop:
.... print t.timeit()
....
0.0822348594666
0.0836551189423
0.0827491283417
0.0818839073181
0.0807418823242
0.0863690376282
0.0951108932495
0.0798268318176
0.080157995224
0.081778049469

# t.repeat with 10 outputs (linebreaks added):
[0.074424982070922852,
0.074212789535522461,
0.074655055999755859,
0.074471950531005859,
0.074034929275512695,
0.074390172958374023,
0.074491024017333984,
0.074390172958374023,
0.074035882949829102,
0.076071023941040039]

There is definitely something fishy going on here.

Also, I would
expect the "pass" statement to be the fastest to execute and therefore the
least accurate to measure.

The problem happens with more complicated tests as well, as long as
they aren't too complicated. But you are right that for anything
significant, the noise dominates.

I'd still like to understand why this happens. The t.repeat method is
very simple:

r = []
for i in range(repeat):
t = self.timeit(number)
r.append(t)

Hmm, if I type this at the python prompt:

r = []
for i in range(1): # Note: only one loop!
ti = t.timeit()
r.append(ti)
print r

I get data that agrees with t.repeat but disagrees with:

for i in range(1):
print t.timeit()

or

t.timeit()

or

ti=t.timeit()
print ti

The last three are *slower* than the one that uses append.

This happens with timeit in 2.4 too, which disables garbage collection
during the timing, so I don't see why the two methods should produce
different answers.

Further clues:
.... print t.timeit()
....

0.0794830322266
....etc...

0.089087963104248047

Could it have something to do with the namespace in effect?

Dan

 

[Peter Otten]

Hmm, if I type this at the python prompt:

r = []
for i in range(1): # Note: only one loop!
ti = t.timeit()
r.append(ti)
print r

I get data that agrees with t.repeat but disagrees with:
....

t.timeit()

You could try "intermediate simplifications" to spot the culprit:

r = [None]
for i in range(1):
r = t.timeit()

and

for i in range(1):
ti = t.timeit()

I've no idea what's happening.

Peter