[New-bugs-announce] [issue45261] Unreliable (?) results from timeit (cache issue?)

[Tim Holy]

New submission from Tim Holy <tim.holy at gmail.com>:

This is a lightly-edited reposting of https://stackoverflow.com/questions/69164027/unreliable-results-from-timeit-cache-issue

I am interested in timing certain operations in numpy and skimage, but I'm occasionally seeing surprising transitions (not entirely reproducible) in the reported times. Briefly, sometimes timeit returns results that differ by about 5-fold from earlier runs. Here's the setup:

import skimage
import numpy as np
import timeit

nrep = 16

def run_complement(img):
    def inner():
        skimage.util.invert(img)
    return inner

img = np.random.randint(0, 65535, (512, 512, 3), dtype='uint16')

and here's an example session:

In [1]: %run python_timing_bug.py

In [2]: t = timeit.Timer(run_complement(img))

In [3]: t.repeat(nrep, number=1)
Out[3]: 
[0.0024439050030196086,
 0.0020311699918238446,
 0.00033007100864779204,
 0.0002889479947043583,
 0.0002851780009223148,
 0.0002851030003512278,
 0.00028487699455581605,
 0.00032116699730977416,
 0.00030912700458429754,
 0.0002877369988709688,
 0.0002840430097421631,
 0.00028515000303741544,
 0.00030791999597568065,
 0.00029302599432412535,
 0.00030723700183443725,
 0.0002916679950430989]

In [4]: t = timeit.Timer(run_complement(img))

In [5]: t.repeat(nrep, number=1)
Out[5]: 
[0.0006320849934127182,
 0.0004014919977635145,
 0.00030359599622897804,
 0.00029224599711596966,
 0.0002907510061049834,
 0.0002920039987657219,
 0.0002918920072261244,
 0.0003095199936069548,
 0.00029789700056426227,
 0.0002885590074583888,
 0.00040198900387622416,
 0.00037131100543774664,
 0.00040271600300911814,
 0.0003492849937174469,
 0.0003378120018169284,
 0.00029762100894004107]

In [6]: t = timeit.Timer(run_complement(img))

In [7]: t.repeat(nrep, number=1)
Out[7]: 
[0.00026428700948599726,
 0.00012682100350502878,
 7.380900206044316e-05,
 6.346100417431444e-05,
 6.29679998382926e-05,
 6.278700311668217e-05,
 6.320899410638958e-05,
 6.25409884378314e-05,
 6.262199894990772e-05,
 6.247499550227076e-05,
 6.293901242315769e-05,
 6.259800284169614e-05,
 6.285199197009206e-05,
 6.293600017670542e-05,
 6.309800664894283e-05,
 6.248900899663568e-05]

Notice that in the final run, the minimum times were on the order of 0.6e-4 vs the previous minimum of ~3e-4, about 5x smaller than the times measured in previous runs. It's not entirely predictable when this "kicks in."

The faster time corresponds to 0.08ns/element of the array, which given that the 2.6GHz clock on my i7-8850H CPU ticks every ~0.4ns, seems to be pushing the limits of credibility (though thanks to SIMD on my AVX2 CPU, this cannot be entirely ruled out). My understanding is that this operation is implemented as a subtraction and most likely gets reduced to a bitwise-not by the compiler. So you do indeed expect this to be fast, but it's not entirely certain it should be this fast, and in either event the non-reproducibility is problematic.

It may be relevant to note that the total amount of data is

In [15]: img.size * 2
Out[15]: 1572864

and lshw reports that I have 384KiB L1 cache and 1536KiB of L2 cache:

In [16]: 384*1024
Out[16]: 393216

In [17]: 1536*1024
Out[17]: 1572864

So it seems possible that this result is being influenced by just fitting in L2 cache. (Note that even in the "fast block," the first run was not fast.) If I increase the size of the image:

 img = np.random.randint(0, 65535, (2048, 2048, 3), dtype='uint16')

then my results seem more reproducible in the sense that I have not yet seen one of these transitions.

----------
components: Library (Lib)
messages: 402411
nosy: timholy
priority: normal
severity: normal
status: open
title: Unreliable (?) results from timeit (cache issue?)
type: behavior
versions: Python 3.8

_______________________________________
Python tracker <report at bugs.python.org>
<https://bugs.python.org/issue45261>
_______________________________________