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
.