Hypothesis: Object generation causes unreliable test times

[mchlnix]

My tests are failing in a CI, because from time to time a hypothesis test takes orders of magnitude longer than normal and I get this error message:

Unreliable test timings! On an initial run, this test took 1624.68ms, which exceeded the deadline of 200.00ms, but on a subsequent run it took 0.15 ms, which did not. If you expect this sort of variability in your test timings, consider turning deadlines off for this test by setting deadline=None.

I'm just creating an object and testing its negation operator. Pretty much a useless test, but no black magic or i/o involved, either.

Further down I have a minimal example showcasing how much the execution time varies even when pretty much nothing happens in the code. Is there an explanation for this?

> pytest --hypothesis-show-statistics test.py 
=============================================== test session starts ===============================================
platform linux -- Python 3.6.8, pytest-5.1.2, py-1.8.0, pluggy-0.13.0
hypothesis profile 'default' -> database=DirectoryBasedExampleDatabase('/home/michael/Gits/minimal_hypothesis_example/.hypothesis/examples')
rootdir: /home/michael/Gits/minimal_hypothesis_example
plugins: hypothesis-4.36.1
collected 1 item                                                                                                  

test.py .                                                                                                   [100%]
============================================== Hypothesis Statistics ==============================================

test.py::test_timing:

  - 100000 passing examples, 0 failing examples, 0 invalid examples
  - Typical runtimes: < 1ms
  - Fraction of time spent in data generation: ~ 42%
  - Stopped because settings.max_examples=100000
  - Events:
    *  99.93%, Time: 0 ms
    *   0.06%, Time: 1 ms
    *   0.00%, Time: 119 ms
    *   0.00%, Time: 120 ms
    *   0.00%, Time: 138 ms
    *   0.00%, Time: 152 ms
    *   0.00%, Time: 162 ms
    *   0.00%, Time: 166 ms
    *   0.00%, Time: 30 ms

test.py

from time import time
from unittest.mock import Mock

from hypothesis import given, settings, event
from hypothesis.strategies import integers


@given(integers())
@settings(max_examples=100000)
def test_timing(_):
    start = time()

    Mock()

    event(f"Time: {int((time() - start) * 1000)} ms")

[Zac-HD]

Looks like creating a Mock can just be slow sometimes - I'd suspect a cache somewhere.

The best solution is probably just to increase the deadline setting to two or three seconds, so it doesn't get triggered!

[mchlnix]

Thanks for the fast reply.

It happens with some of my own objects as well. One of which is a glorified tuple with some __methods__ replaced.

This can't be an uncommon problem, can it? If it helps, it happens more often in the CI with xdist, although the minimal example ran locally without any other plugins.

Btw: Considering the cache, in the real tests, that fail because of the deadline, it is often times the 10.000+ th test, that fails.

Could it maybe have something to do with the python interpreter running out of memory? I wouldn't know how, since I only use the normal 200 max_examples in my CI, but who knows?

[Zac-HD]

I haven't heard of this happening to anyone else, and we're fairly good about not growing memory use indefinitely...

If you can share a minimal reproducing example I can take a look, but honestly I'd just disable the deadline for this test - it's meant to inform you about pathological cases, and this looks like it's almost always fast.

[mchlnix]

How more minimal would the example need to be?

[Zac-HD]

Reproducing is more important, minimal just makes it faster for me to understand. Few dependencies and few files is enough if that helps, there's no strict rule!

[mchlnix]

So the above example doesn't reproduce it enough, or do you think that might just be a coincidence with Mock?

I can see if I can minimize one of the production code tests, that fails this way (every 10th test run, maybe) but at least one of these also used a mock just to see, that a callback was called so while it isn't just tests with Mock it also definitely happens with tests where Mock() used up the bulk of the time.

I'll increase the deadline for now, but I agree, that this should be a widespread problem, if it was actually (only) hypothesis' fault.

[mchlnix]

After increasing the deadline, now we get this error:

mock_object = <Mock id='140665440770200'>

    @given(dimension=dimensions(), width=floats())
>   def test_callback_for_width(mock_object, dimension, width):
E   hypothesis.errors.FailedHealthCheck: Data generation is extremely slow: Only produced 6 valid examples in 5.42 seconds (0 invalid ones and 0 exceeded maximum size). Try decreasing size of the data you're generating (with e.g.max_size or max_leaves parameters).
E   See https://hypothesis.readthedocs.io/en/latest/healthchecks.html for more information about this. If you want to disable just this health check, add HealthCheck.too_slow to the suppress_health_check settings for this test.

../util/test_dimension.py:48: FailedHealthCheck
---------------------------------- Hypothesis ----------------------------------
You can add @seed(107065245528392312660426352172411457389) to this test or run pytest with --hypothesis-seed=107065245528392312660426352172411457389 to reproduce this failure.

@composite
def dimensions(draw):
    return Dimension(w=draw(floats()), h=draw(floats()))

@pytest.fixture
def mock_object():
    # initializing a Mock object sometimes takes up to 200 ms, which makes hypothesis tests timeout
    # so take this out of the individual test and into a fixture, instead
    return Mock()

It only seems to happen, if a lot of workers in the CI are at it at the same time, but still. That's a lot.

I think it probably has something to do with the Ci, though. Not sure if hypothesis just gets hit the hardest.

[mchlnix]

OK:

So in production we also use xdist and the tests fail, when I start the maximum number of workers in the CI. That reaches 100% cpu at some point.
Since hypothesis is the only test, that actually cares about timing, it is the first/only one to actually fail because of that.
So that is probably the reason. It must be pretty heavy, considering that one hypothesis run took 10s, which is 30.000 times slower than the next one.

So hypothesis is not to blame and is only a victim of the context switching of the host, I think.

[Zac-HD]

Yep, that's what I suspected. Specifically you probably have more workers than physical cores, so they get starved of CPU time.

(this can even happen with -n auto, since thw system might report logicalcores. That's fine for IO-dominated loads, but testing tends to be CPU-limited)

Closing this issue because we can't help by changing Hypothesis. I also want to say thanks for a great writeup and ongoing investigation!