Spurius benchmark fail in unit tests

[pmrv]

There's a test from the FileTable that sometimes fails and sometimes now, with the following error:

 ======================================================================
FAIL: test_re_initialization (database.test_filetable.TestFileTable.test_re_initialization)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\a\pyiron_base\pyiron_base\tests\database\test_filetable.py", line 52, in test_re_initialization
    self.assertTrue(
AssertionError: False is not true : We promise re-initialization to be much faster, but got times 0.00e+00 for the first and 0.00e+00 for the second

details

I tend to just restart them until it works and it doesn't come up often, but can that be made more robust? Seems like the actual test is just a bit too fast and the timing becomes degenerate.

[liamhuber]

The fact that they are both flat zero for time is super suspicious...

[liamhuber]

Indeed, that is incredibly weird. I just ran the test a bunch of times on my machine and consistently get ['1.17e-02', '1.00e-05'] for the two times. The way I can get 0.00e+00 for both is by completely commenting out the file table initializations. Even putting a trivial operation in its place gives O(e-6).

E.g.

    def test_re_initialization(self):
        start = time()
        x = 5+1
        # ft = FileTable(self.loc1)
        first_initialization = time() - start

        start = time()
        y = 10/3
        # ft_reinitialized = FileTable(self.loc1)
        second_initialization = time() - start

        print([f"{t:.2e}" for t in [
            # master_init, m2,
            first_initialization, second_initialization
        ]])

[liamhuber]

Ok, interesting. Actually, if I re-run it with the simple math operations sometimes it comes out as e-6 to e-8, but sometimes it's coming out as completely zero.

So under some conditions the filetable instantiation is getting completely trivial, even on the first go?

[liamhuber]

This snippet yields false:

        times = []
        for n in range(500):
            start = time()
            FileTable(self.loc1)
            dt = time() - start
            times.append(dt)
        print(any(t < 1e-8 for t in times))

What's wild is that even if I go over to FileTable.__init__ and replace its entire body with pass, it still yields False. So whatever is happening to get these 0.00e00 is totally wild, because even just instantiating a totally gutted FileTable is still not fast enough to cause the time differential to bug out.

EDIT: snippet indentation

EDIT: changing 500 -> 50000 still doesn't give any zero times, so it's not just sampling

[liamhuber]

Sorry @pmrv, I'm at a loss.

Your linked failure was windows -- are you always seeing it on the same OS?

[pmrv]

Thanks for testing it out. I hadn't paid attention yet to which OS this appears on, but can keep an eye. Actually it's a good hint, maybe the default timer used by time.time on windows sucks. Python docs only mention that it is not guaranteed to be more granular than seconds and not even monotonic, so probably a good idea to just change it to time.perf_counter, anyway.

[liamhuber]

maybe the default timer used by time.time on windows sucks

I guess I wouldn't be particularly surprised...

so probably a good idea to just change it to time.perf_counter, anyway.

Cool, didn't know about that! I can patch the test later today and hopefully that resolves the issue.