Differences between performance measurement techniques for a single method in Python

Question

I am trying to figure out how long does it take for my LDA classifier to predict the class of a single 1080 dimensional vector. I read these threads:

• Measure time elapsed in Python?
• timeit versus timing decorator
• How do I get time of a Python program's execution?

and found out there are several ways to do this. I tested few of them but they produced very different results.

time module:

import time
start = time.time()
lda.predict(sample)
end = time.time()
print(str((end-start)*10**6), 'µs')
>>> 1452.9228210449219 µs

timeit module's default_timer:

from timeit import default_timer as timer
start = timer()
lda.predict(sample)
end = timer()
print(str((end-start)*10**6), 'µs')
>>> 979.6129997994285 µs

iPython %timeit magic function:

%timeit lda.predict(sample)
>>> 52 µs ± 873 ns per loop (mean ± std. dev. of 7 runs, 10000 loops each)

Am I doing something ridiculous here or is there some other explanation for the differences? Which one to trust? Thank you in advance.

Answer 1

Firstly, there may be several clocks in your system, with different resolutions and precisions. So, one clock may be really accurate (gimme deez nanoseconds, m8!), while another one may only measure time in whole days. There are probably none that actually do the latter, but you get the point. I also found a pretty interesting website that explains how computers measure time.

Secondly, the CPU doesn't always do your task at the same speed as it has plenty of other stuff to do! It's actually constantly switching between tons of different tasks incredibly quickly, and to us, slow humans, it looks like it does all of this simultaneously. Well, nope. So, right now your CPU might be a bit busier than it was milliseconds before, and this means your task may be executed milliseconds later, or the other way round.

As for iPython's %timeit code, it, unlike the other methods you used, runs code multiple times, so, while the first run may take a lot of time, subsequent runs may be much faster due to caching. So, in this case, during the first run the result is actually calculated (which is slow) then just dumped to memory, and the other 69999 runs merely fetch that result, which happens to be faster than doing the computations. I don't think you can disable caching easily as a cache is literally built into the CPU, so results of any repetitive job may get cached.

---

The latter may not be the case, though. It turns out that %timeit uses (a subclass of) timeit.Timer (definition at line 139 of iPython's source code and usage at line 945)^* that disables garbage collection before measuring time. And that most likely is the reason for such drastic speedup since garbage collection takes a lot of time, and provided that your code is rather complicated, the GC is bound to have lots of work to do.

---

^* Yeah, I know you can have links directly to some line, but that doesn't work for me for some reason, sorry about that.