Unexpected timing results

[Steven D'Aprano]

On Thu, 23 Feb 2006 10:07:14 -0600, Larry Bates wrote:

>> Of course I expect timer2 should take longer to execute in total,
>> because it is doing a lot more work. But it seems to me that all that
>> extra work should not affect the time measured, which (I imagine) should
>> be about the same as timer1. Possibly even less as it isn't timing the
>> setup of the for loop.

...

> In timer2 you are making a million extra calls to timer()
> function and doing a million additions and a million
> subtractions that are not being done in timer1() function.
> I think that is where your "extra" time is located.

But those extra additions, subtractions, etc. are not being timed, because
they are outside the part where the stopwatch is ticking, in a manner of
speaking.

I know that timer2 will take longer to execute than timer1. That's not
the surprising bit. But I'm not measuring all the execution time, only
part of it, and not all that execution time is being timed.

The only extra work I can see is a call to timer() each loop. The first
call shouldn't count, because it happens before the clock starts. Is
calling time.time() really such as expensive operation, especially when
I've rebound the name so as to avoid a name lookup?

I guess it is: I've run two more tests, both going back to the form of
timer1, but changing the function being timed. The first uses math.sin.
The second uses time.timer.

Here is the code:

def timer3():
    timer = time.time
    func = math.sin
    itr = [None] * 1000000
    t0 = timer()
    for _ in itr:
        func(0.1)
    t1 = timer()
    return t1 - t0

def timer4():
    timer = time.time
    func = timer
    itr = [None] * 1000000
    t0 = timer()
    for _ in itr:
        func()
    t1 = timer()
    return t1 - t0

And the results:

>>> timer.timer3()
0.64760088920593262
>>> timer.timer4()
5.2274949550628662



It looks like the time function under Linux at least is very slow.


-- 
Steven.