Python test test_variants_different_dtypes[brotli] sometimes times out

[musicinmybrain]

Environment:

• Fedora Linux 39
• x86_64 architecture
• Python 3.12.1

I originally saw this while working on a python-cramjam package for Fedora Linux, but I’m able to reproduce it in a simple virtual environment.

To reproduce:

Check out current master, a1c0c02, and cd to the cramjam-python/ directory.

rm -rf _e && python3 -m build && python3 -m venv _e && . _e/bin/activate && pip install ./dist/cramjam-2.7.0-cp312-cp312-linux_x86_64.whl && pip install numpy pytest pytest-xdist hypothesis && python3 -m pytest -v -n 16 tests/ && deactivate

Sometimes, all tests pass:

================================================ 564 passed in 34.75s ================================================

…but if I run the command repeatedly, I often see this:

====================================================== FAILURES ======================================================
_______________________________________ test_variants_different_dtypes[brotli] _______________________________________
[gw1] linux -- Python 3.12.1 /home/ben/src/forks/cramjam/cramjam-python/_e/bin/python3

variant_str = 'brotli'

    @pytest.mark.parametrize("variant_str", VARIANTS)
>   @given(arr=st_np.arrays(st_np.scalar_dtypes(), shape=st.integers(0, int(1e5))))

tests/test_variants.py:35: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

args = ('brotli', array([0.+0.j, 0.+0.j, 0.+0.j, ..., 0.+0.j, 0.+0.j, 0.+0.j])), kwargs = {}
arg_drawtime = 0.0020151169737800956, initial_draws = 1, start = 463383.986474383, result = None
finish = 463385.225831358, internal_draw_time = 0, runtime = datetime.timedelta(seconds=1, microseconds=239357)
current_deadline = timedelta(milliseconds=1000)

    @proxies(self.test)
    def test(*args, **kwargs):
        arg_drawtime = sum(data.draw_times)
        initial_draws = len(data.draw_times)
        start = time.perf_counter()
        try:
            result = self.test(*args, **kwargs)
        finally:
            finish = time.perf_counter()
            internal_draw_time = sum(data.draw_times[initial_draws:])
            runtime = datetime.timedelta(
                seconds=finish - start - internal_draw_time
            )
            self._timing_features = {
                "time_running_test": finish - start - internal_draw_time,
                "time_drawing_args": arg_drawtime,
                "time_interactive_draws": internal_draw_time,
            }
    
        current_deadline = self.settings.deadline
        if not is_final:
            current_deadline = (current_deadline // 4) * 5
        if runtime >= current_deadline:
>           raise DeadlineExceeded(runtime, self.settings.deadline)
E           hypothesis.errors.DeadlineExceeded: Test took 1239.36ms, which exceeds the deadline of 1000.00ms
E           Falsifying example: test_variants_different_dtypes(
E               variant_str='brotli',
E               arr=array([0.+0.j, 0.+0.j, 0.+0.j, ..., 0.+0.j, 0.+0.j, 0.+0.j]),
E           )

_e/lib64/python3.12/site-packages/hypothesis/core.py:845: DeadlineExceeded
----------------------------------------------------- Hypothesis -----------------------------------------------------
WARNING: Hypothesis has spent more than five minutes working to shrink a failing example, and stopped because it is making very slow progress.  When you re-run your tests, shrinking will resume and may take this long before aborting again.
PLEASE REPORT THIS if you can provide a reproducing example, so that we can improve shrinking performance for everyone.
============================================== short test summary info ===============================================
FAILED tests/test_variants.py::test_variants_different_dtypes[brotli] - hypothesis.errors.DeadlineExceeded: Test took 1239.36ms, which exceeds the deadline of 1000.00ms
===================================== 1 failed, 563 passed in 335.91s (0:05:35) ======================================

… or this:

====================================================== FAILURES ======================================================
_______________________________________ test_variants_different_dtypes[brotli] _______________________________________
[gw1] linux -- Python 3.12.1 /home/ben/src/forks/cramjam/cramjam-python/_e/bin/python3

variant_str = 'brotli'

    @pytest.mark.parametrize("variant_str", VARIANTS)
>   @given(arr=st_np.arrays(st_np.scalar_dtypes(), shape=st.integers(0, int(1e5))))

tests/test_variants.py:35: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

args = ('brotli', array([0.+0.j, 0.+0.j, 0.+0.j, ..., 0.+0.j, 0.+0.j, 0.+0.j])), kwargs = {}
arg_drawtime = 0.0022371799568645656, initial_draws = 1, start = 464013.190208792, result = None
finish = 464014.414762949, internal_draw_time = 0, runtime = datetime.timedelta(seconds=1, microseconds=224554)
current_deadline = timedelta(milliseconds=1000)

    @proxies(self.test)
    def test(*args, **kwargs):
        arg_drawtime = sum(data.draw_times)
        initial_draws = len(data.draw_times)
        start = time.perf_counter()
        try:
            result = self.test(*args, **kwargs)
        finally:
            finish = time.perf_counter()
            internal_draw_time = sum(data.draw_times[initial_draws:])
            runtime = datetime.timedelta(
                seconds=finish - start - internal_draw_time
            )
            self._timing_features = {
                "time_running_test": finish - start - internal_draw_time,
                "time_drawing_args": arg_drawtime,
                "time_interactive_draws": internal_draw_time,
            }
    
        current_deadline = self.settings.deadline
        if not is_final:
            current_deadline = (current_deadline // 4) * 5
        if runtime >= current_deadline:
>           raise DeadlineExceeded(runtime, self.settings.deadline)
E           hypothesis.errors.DeadlineExceeded: Test took 1224.55ms, which exceeds the deadline of 1000.00ms
E           Falsifying example: test_variants_different_dtypes(
E               variant_str='brotli',
E               arr=array([0.+0.j, 0.+0.j, 0.+0.j, ..., 0.+0.j, 0.+0.j, 0.+0.j]),
E           )

_e/lib64/python3.12/site-packages/hypothesis/core.py:845: DeadlineExceeded
============================================== short test summary info ===============================================
FAILED tests/test_variants.py::test_variants_different_dtypes[brotli] - hypothesis.errors.DeadlineExceeded: Test took 1224.55ms, which exceeds the deadline of 1000.00ms
=========================================== 1 failed, 563 passed in 31.16s ===========================================

---

In my testing, it seems like increasing the deadline, e.g.

diff --git a/cramjam-python/tests/test_variants.py b/cramjam-python/tests/test_variants.py
index 4ee4ca3..97e287a 100644
--- a/cramjam-python/tests/test_variants.py
+++ b/cramjam-python/tests/test_variants.py
@@ -12,7 +12,7 @@ VARIANTS = ("snappy", "brotli", "bzip2", "lz4", "gzip", "deflate", "zstd")
 
 # Some OS can be slow or have higher variability in their runtimes on CI
 settings.register_profile(
-    "local", deadline=timedelta(milliseconds=1000), max_examples=100
+    "local", deadline=timedelta(milliseconds=10000), max_examples=100
 )
 settings.register_profile("CI", deadline=None, max_examples=25)
 if os.getenv("CI"):

is enough to resolve the problem. Note that I am testing on a fairly fast workstation (AMD Ryzen 9 5950X) ; I haven’t yet tried this on slower CI machines, particularly those of other architectures like ppc64le.

[milesgranger]

Hrmm..I think I remember seeing this at least once before, but for whatever reason was taken up w/ something else.

My first estimation would be that as this is the slowest codec, it's probably getting some larger inputs that is causing it to pass the deadline. I'm fine with extending the deadline, but as you mention other platforms may still struggle. Slightly more inclined to limit the upper bound of the input lengths in hypothesis. Anything larger than the largest block size would probably be sufficient.

Thanks for the report. 👍

[musicinmybrain]

My first estimation would be that as this is the slowest codec, it's probably getting some larger inputs that is causing it to pass the deadline.

👍

I'm fine with extending the deadline, but as you mention other platforms may still struggle.

As a follow-up, I just got to the point where I was able to do a test build of a future python-cramjam package in COPR, and I found that the arbitrarily-chosen 10-second limit was enough for for the tests to succeed on all of Fedora’s primary architectures (x86_64, i686, ppc64le, aarch64, s390x) – at least once, and at least for the particular builder machines I happened to get this time. Obviously, there always exist other architectures and slower machines, and I may have gotten lucky with randomized inputs…

Slightly more inclined to limit the upper bound of the input lengths in hypothesis. Anything larger than the largest block size would probably be sufficient.

This wasn’t obvious to me, but seems more elegant if it proves to be sufficient. I’m happy to test a proposed change on the above-mentioned architectures, if that helps.

Thanks for the report. 👍

You’re welcome!

[musicinmybrain]

I tested 67f6902 as a patch for the released Python package, version 2.7.0. As expected, it does appear to fix the timeouts on all Fedora primary architectures without needing to increase the deadline beyond one second.

[milesgranger]

Great to hear, thanks for that @musicinmybrain!