Profiling weirdness: Timer.timeit(), fibonacci and memoization

[Steven D'Aprano]

On Sat, 02 Aug 2008 16:14:11 -0500, Rob Williscroft wrote:

> Stefaan Himpe wrote in news:2m3lk.118118$9I1.20910 at newsfe16.ams2 in
> comp.lang.python:
> 
>> Nothing weird about this ...
>> The difference will become larger as your input value becomes larger.
>> 
>> You can easily understand why if you try to calculate fib(10) by hand,
>> i.e. work through the algorithm with pencil and paper, then compare the
>> work you have to do to the memoized version which just takes fib(9) and
>> fib(8) from memory and adds them together.
>> 
>> 
> I think you missed the point.
> 
> The problem is that the un-decorated, loop only version takes 35 seconds
> when called by timeit.Timer.  However if you apply the decorator it
> takes less that a second.  In *both* cases the function (fib) only gets
> called once.

I think you are completely misreading the results of the Timeit calls. 
That's not correct: you're calling it one million times, not once.

You should apply a "sanity check" to results. At the interactive console, 
call the undecorated fib(100) once. Does it take 35 seconds? If so, your 
computer is terribly slow -- on mine, it returns instantly.

Note that in your email, you showed only half the output:


[quote]
t1 = Timer('fib(s)', 'from __main__ import fib, s')
t2 = Timer('fibmem(s)', 'from __main__ import fibmem, s')
t1.repeat(number=1)
t2.repeat(number=1)
print t1.timeit()
print t2.timeit()


>>>
35.3092010297
1.6516613145
[end quote]

You had two calls to Timer.repeat() methods, and you didn't show the 
output. *They* call the Fibonacci functions once. When I do that, I get 
output looking like this:

>>> t1 = Timer('fib(s)', 'from __main__ import fib, s')
>>> t1.repeat(number=1)
[7.9870223999023438e-05, 5.5074691772460938e-05, 5.4121017456054688e-05]

You then call the Timer.timeit() method, which calls the function one 
million times by default. That's the output you show: notice that 35s 
divided by one million is 3.5e-05s, around what I get using the repeat() 
method. There's no mystery.


> Note, I timed the call fib(100) with time.clock() and got a value of
> less than 1 ms, the memozed version takes about 10 times longer.

You shouldn't give much credence to timing results from calling a 
function once (unless the function does a *lot* of work). Your operating 
system is doing all sorts of work in the background. It can easily 
interrupt your process mid-calculation to do something else, and your 
timing code will then include that. You'll then wrongly conclude that the 
function is slower than it really is.

Also, keep in mind that time.clock() is likely to be significantly less 
accurate if you are using Linux. The timeit module automatically choose 
the best function to use (time.clock vs time.time) for you.

> So the question is: whats going on with timeit.Timer ?

As far as I can see, nothing. I think you have misunderstood the results 
you got.



-- 
Steven