Simple Python Speed Benchmark

[Andrew Dalke]

engsolnom at ipns.com:
> I was curious how long Python takes just to read and display time.clock()
  ...
> I was amazed at the difference in speed depending on when/how the clock
times were converted to
> milliseconds....almost 4 to 1...as indicated in the RESULTS below. I
understand the variation in the
> times is probably due to other running processes.
>
> Any explanation?

There are quite a few things here.

First, if you look at the "Test 3:" and "Test 4:" numbers you'll see it's
only
2 times slower, not 4.  Let's start with that case, where the tests you make
are in a function.  You can see the PVM op codes generated by using
the dis module

>>> def spam():
... t1 = time.clock()
...
>>> import dis
>>> dis.dis(spam)
  2           0 LOAD_GLOBAL              0 (time)
              3 LOAD_ATTR                1 (clock)
              6 CALL_FUNCTION            0
              9 STORE_FAST               0 (t1)
             12 LOAD_CONST               0 (None)
             15 RETURN_VALUE
>>> def spam2():
... t1 = time.clock() * 1000
...
>>> dis.dis(spam2)
  2           0 LOAD_GLOBAL              0 (time)
              3 LOAD_ATTR                1 (clock)
              6 CALL_FUNCTION            0
              9 LOAD_CONST               1 (1000)
             12 BINARY_MULTIPLY
             13 STORE_FAST               0 (t1)
             16 LOAD_CONST               0 (None)
             19 RETURN_VALUE
>>>

This shows that the "* 1000" is doing two more things; load the
constant "1000" and then do a binary multiply.  The obvious
conclusion is that the factor of 2 slowdown comes from this step.
(That actually surprises me.  Function call overhead should be
much more than a simple multiply.)

The next is the precision of the clock.  The numbers generated
are pretty well quantized.  For example, '0.014527' comes up
quite frequently as does '0.005867'.  It appears that your clock
has a resolution of about 0.0003, which is 5% of the smaller
numbers or 2% of the bigger ones.  If the time slices are just
at the wrong point then you may get a systematic error of up
to about 6% (ie, if the time.clock is done in just under an
integral time quantum while the time.clock()*1000 is just over
a quantum).

To get around that, you should do more tests, and not have
the results of one test strongly correlated with the other.
(You do because get_time_1() is always followed with a
get_time_2().)  The easiest way is to use the timeit module,
either on the command-line or interactively, as

>>> import timeit
>>> timeit.Timer("time.clock", "import time").repeat(3, 10000)
[0.0063276180834463958, 0.0066243037524600368, 0.0078663607060889262]
>>> timeit.Timer("time.clock()", "import time").repeat(3, 10000)
[0.054394886949353349, 0.053860182268920198, 0.05341180138486834]
>>> timeit.Timer("time.clock()*1000", "import time").repeat(3, 10000)
[0.057691115018485561, 0.059368981429486212, 0.058075800674146194]
>>>

As you can see, on my box it takes 0.06 microseconds to do
'time.clock', 0.48 microseconds to make the call, and 0.03
microseconds to do the *1000.

Try those on your machine.

                    Andrew
                    dalke at dalkescientific.com