Hypothesis: Test spins for minutes before reporting deadline exceeded

[rsokl]

Hi all!

I am running tests on a Windows 10 machine using the following libraries:

• Python 3.7.1
• pytest-4.0.2, py-1.7.0
• pluggy-0.8.0
• remotedata-0.3.1
• openfiles-0.3.1
• doctestplus-0.2.0
• arraydiff-0.3
• hypothesis-4.4.5

I am returning to an older codebase that had been running hypothesis 3.x. I've upgraded to 4.4.5. A test can spin for several minutes before reporting that the deadline has been exceeded. The test itself can complete successfully in some ~300ms once the deadline is turned off.

If it helps, these tests used the strategy hypothesis.extra.numpy.arrays

Please let me know if there is additional pertinent information I can add. (~I have a hunch that this is a Windows issue. I haven't hit this in Linux for other hypothesis-4.x runs.~).

P.S. My other tests are running so much faster after finally upgrading hypothesis for this project 😄

[Zac-HD]

How long does the test take if you just turn the deadline up to 500ms?

It's possible that the 200ms default deadline is just too short for this test!

[rsokl]

My issue isn't that my test was failing; indeed, increasing the deadline to 400ms did the trick for that test.

The issue is that hypothesis will consistently spin for some 5 - 10 minutes each time it encounters a test that is exceeding its deadline.

[Zac-HD]

Just to clarify, is that 300ms per test case, or 300ms for all examples?

Maybe we should disable shrinking for DeadlineExceeded errors?

[rsokl]

It is 300ms per test case.

I am not sure if this is a shrinking issue. As I mentioned, one of these tests can complete the default 200 max examples in ~400ms. But if I purposefully lower the deadline to be too brief, minutes will pass before a DeadlineExceeded gets reported. Would shrinking in this context cause so many examples (~10K) of the test to be run?

[Zac-HD]

It's certainly possible - shrinking a deadline overrun is about the slowest thing possible here.

You could skip shrinking with the phases setting to check this.

[DRMacIver]

It is almost certainly a shrinking issue, in that DeadlineExceeded test cases are shrunk like any other, so what's presumably happening here is that it's taking a very long time to shrink the error.

This is in some sense working as intended in that it's a deliberate design decision to shrink these, but it's certainly not great that it's taking so long in this case. 😞 I'd rather not disable shrinking for these cases entirely, but it's possible there's something we can do to mitigate the problem.

Are you able to share the original tests?

[DRMacIver]

The most likely scenario here BTW is that the deadline is reliably exceeded for most large examples but few or no small examples. The shrinker is known to take a fairly long time as measured in test executions in that scenario and if on top of that all of the failing tests are slow (because they're deadline tests) it'll add up.

[rsokl]

I wish I could provide a simpler test than this, but most of my tests use a pretty large "test factory" decorator that you would have to pour through.

Here is a test that fails to meet the default deadline and will take minutes to resolve. Please excuse the mess.

It draws in part from a custom strategy, broadcastable_shape, that I define here.

I did verify that, if I simply replace the body of this test with a 1 second sleep, then the test reports DeadlineExceeded in a quick manner. This supports your suspicion that the shrinker is the culprit.

[DRMacIver]

Here is a test that fails to meet the default deadline and will take minutes to resolve.

Just eyeballing this based on the features you're using, my guess is that it probably takes a long time to shrink at the best of times - there's a lot of dependencies in the shape of later generated data on earlier. The shrinker can usually handle this fine, but it'll take longer to do so. A trivial test that always fails (like adding an sleep(1) with a deadline or an assert False) won't take long because it's not hard to find the smallest possible example, but shrinking a non-trivial property is more challenging. If you can see how long it takes with a "realistic" bug (e.g. maybe change your assert_allclose tolerances too low?) that'd be interesting data.

Also FWIW if you upgrade to the latest version (4.4.5 onwards really) you should hopefully find the time spent on this is considerably decreased, though it still won't be fast.

[rsokl]

@DRMacIver thanks for the feedback.

I introduced a "realistic bug" by rounding one of my gradient-arrays to six decimal places before doing the comparison. This causes the test to fail on relatively rare cases.

Time to shrink / report an error on this test:

• realistic/subtle bug: ~20 seconds
• test exceeds 200ms (default) deadline: ~200 seconds

Fortunately I seldom have such subtle bugs in my numerical code. I typically just overlook some mathematical edge case - hypothesis catches and shrinks these cases very quickly (<1s).

Upgrading to 4.4.5 yielded a very nice speedup for these tests! I believe it cut down test time by at least a factor of 2. It's been great :grin:

[Zac-HD]

@rsokl - happy to re-open this issue if you think there's any action we should take, but I think this is just inherent in shrinking a DeadlineExceeded error. At least it's faster in recent versions!

[DRMacIver]

Upgrading to 4.4.5 yielded a very nice speedup for these tests! I believe it cut down test time by at least a factor of 2. It's been great 😁

Good to hear! In which case, I think the right thing to do on our end is just to continue my already intended line of improvements to the shrinker (which is, among other things, intended to help a fair bit with slow and hard to reduce tests) - you might even see another big speedup in shrinking later this week from this.

Having shrinking deadlines be an order of magnitude slower sounds about right, and I'd rather we get that 20s number down than the ratio down.