Repository: scipy/scipy
Pull request: TST: optimize: fix test_milp_timeout
#### Reference issue
Closes gh-17137

#### What does this implement/fix?
gh-17137 `test_milp_timeout` fails on some platforms. Here, we'll try to fix it.

#### Additional information
I removed the `slow` and `timeout` marks to explore what happens on all CI platforms. Before merging, we need to check the `durations` to see if this is running for longer than expected.
With the time limit change, this test passes for me locally. @WarrenWeckesser @andyfaff how about you?

Problem statement:
BUG: optimize: Intermittent failure of `test_milp_timeout_16545`
### Describe your issue.

When I run the `optimize` tests with the main development branch (version `1.10.0.dev0+1987.fa3276a`), the test `test_milp_timeout_16545` often (but not always!) fails.

### Reproducing Code Example

```python
$ python dev.py test -m full -j 9 -s optimize
💻  ninja -C /home/warren/repos/git/forks/scipy/build
ninja: Entering directory `/home/warren/repos/git/forks/scipy/build'
[2/2] Generating scipy/generate-config with a custom command
Build OK
💻  meson install -C build --only-changed
Installing, see meson-install.log...
Installation OK
SciPy from development installed path at: /home/warren/repos/git/forks/scipy/build-install/lib/python3.10/site-packages
Running tests for scipy version:1.10.0.dev0+1987.fa3276a, installed at:/home/warren/repos/git/forks/scipy/build-install/lib/python3.10/site-packages/scipy
============================================================== test session starts ===============================================================
platform linux -- Python 3.10.1, pytest-6.2.5, py-1.11.0, pluggy-1.0.0
rootdir: /home/warren/repos/git/forks/scipy, configfile: pytest.ini
plugins: forked-1.4.0, timeout-2.1.0, hypothesis-6.35.0, xdist-2.5.0
gw0 [2281] / gw1 [2281] / gw2 [2281] / gw3 [2281] / gw4 [2281] / gw5 [2281] / gw6 [2281] / gw7 [2281] / gw8 [2281]
.......................................................................................................................................... [  6%]
..................................................................................................................................ss...... [ 12%]
.......................................................................................................................................... [ 18%]
.........................................................................................s................................................. [ 24%]
..................................................................................................s...X.........s.sX...................... [ 30%]
.......................s.................................................................................................................. [ 36%]
...........ssssss.s..................................................................................x.................................... [ 42%]
.........................................x................................................................................................ [ 48%]
.......................................................................................................................................... [ 54%]
................................................................s......s.s................................................................ [ 60%]
.....................................X.............................X................X.....................................X............... [ 66%]
.........................................................................s..ss.ssss.s.s...ss...ssss..ssss..ssss.ss.ss.ss.s.sss..ssss..ssss [ 72%]
.s.sss.ss.s.ss.ss..ssss.sss.ss.s.ss.ss.ss..sss.ss.ss.s..s.s....s..s..ss...ss.........................s.sss..sss.s.sss.ss..ssss.sss..sss.ss [ 78%]
.ss.ss..sss.sss.ss..sss.ss.ss.ss.ss.ss.s.ss.ss.ss..ss.sss.sss.ss.ss..ss.ss.ssss.s.s..s.ss.s.s............................................. [ 84%]
..................................................................x....................................................................... [ 90%]
.................................................................................................................................x........ [ 96%]
............................................F...................X.......                                                                   [100%]
==================================================================== FAILURES ====================================================================
____________________________________ test_milp_timeout_16545[options0-Time limit reached. (HiGHS Status 13:] _____________________________________
[gw5] linux -- Python 3.10.1 /home/warren/py3.10.1/bin/python
scipy/optimize/tests/test_milp.py:307: in test_milp_timeout_16545
    assert res.message.startswith(msg)
E   AssertionError: assert False
E    +  where False = <built-in method startswith of str object at 0x7f6878265450>('Time limit reached. (HiGHS Status 13:')
E    +    where <built-in method startswith of str object at 0x7f6878265450> = 'Optimization terminated successfully. (HiGHS Status 7: Optimal)'.startswith
E    +      where 'Optimization terminated successfully. (HiGHS Status 7: Optimal)' =         message: Optimization terminated successfully. (HiGHS Status 7: Optimal)\n        success: True\n         status...00  0.000e+00 ...  0.000e+00  0.000e+00]\n mip_node_count: 2715\n mip_dual_bound: -11.00000000000001\n        mip_gap: 0.0.message
        A          = array([[1, 2, 2, ..., 4, 0, 0],
       [4, 1, 2, ..., 0, 4, 4],
       [4, 1, 1, ..., 1, 4, 3],
       ...,
       [4, 0, 4, ..., 4, 1, 3],
       [4, 1, 3, ..., 2, 0, 2],
       [2, 2, 1, ..., 2, 1, 2]])
        b_lb       = array([-inf, -inf, -inf, -inf, -inf, -inf, -inf, -inf, -inf, -inf, -inf,
       -inf, -inf, -inf, -inf, -inf, -inf, -i...f, -inf, -inf, -inf, -inf, -inf,
       -inf, -inf, -inf, -inf, -inf, -inf, -inf, -inf, -inf, -inf, -inf,
       -inf])
        b_ub       = array([25, 25, 25, 25, 25, 25, 25, 25, 25, 25, 25, 25, 25, 25, 25, 25, 25,
       25, 25, 25, 25, 25, 25, 25, 25, 25, ...25, 25, 25, 25, 25, 25, 25, 25, 25, 25, 25, 25, 25,
       25, 25, 25, 25, 25, 25, 25, 25, 25, 25, 25, 25, 25, 25, 25])
        c_vector   = array([-1., -1., -1., -1., -1., -1., -1., -1., -1., -1., -1., -1., -1.,
       -1., -1., -1., -1., -1., -1., -1., -1.,...  -1., -1., -1., -1., -1., -1., -1., -1., -1., -1., -1., -1., -1.,
       -1., -1., -1., -1., -1., -1., -1., -1., -1.])
        constraints = <scipy.optimize._constraints.LinearConstraint object at 0x7f6878230f70>
        integrality = array([1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1.,
       1., 1., 1., 1., 1., 1., 1., 1., 1., ...1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1.,
       1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1.])
        msg        = 'Time limit reached. (HiGHS Status 13:'
        options    = {'time_limit': 10}
        res        =         message: Optimization terminated successfully. (HiGHS Status 7: Optimal)
        success: True
         status...00  0.000e+00 ...  0.000e+00  0.000e+00]
 mip_node_count: 2715
 mip_dual_bound: -11.00000000000001
        mip_gap: 0.0
        rng        = Generator(PCG64) at 0x7F6882521540
        variable_bounds = Bounds(array([0., 0., 0., 0., 0., 0., 0., 0., 0., 0., 0., 0., 0., 0., 0., 0., 0.,
       0., 0., 0., 0., 0., 0., 0., 0...., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1.,
       1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1.]))
        variable_lb = array([0., 0., 0., 0., 0., 0., 0., 0., 0., 0., 0., 0., 0., 0., 0., 0., 0.,
       0., 0., 0., 0., 0., 0., 0., 0., 0., ...0., 0., 0., 0., 0., 0., 0., 0., 0., 0., 0., 0., 0.,
       0., 0., 0., 0., 0., 0., 0., 0., 0., 0., 0., 0., 0., 0., 0.])
        variable_ub = array([1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1.,
       1., 1., 1., 1., 1., 1., 1., 1., 1., ...1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1.,
       1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1., 1.])
============================================================ short test summary info =============================================================
FAILED scipy/optimize/tests/test_milp.py::test_milp_timeout_16545[options0-Time limit reached. (HiGHS Status 13:] - AssertionError: assert False
======================================= 1 failed, 2084 passed, 185 skipped, 4 xfailed, 7 xpassed in 40.64s =======================================
```


### Error message

```shell
See above.
```


### SciPy/NumPy/Python version information

1.10.0.dev0+1987.fa3276a 1.24.0.dev0+837.g9c5a2b41c sys.version_info(major=3, minor=10, micro=1, releaselevel='final', serial=0)

Hints from issue discussion:
This fails consistently for me. The test tries to assert a time limit of 10 seconds. That's not going to be reliable it looks like - unless the `10` means 10 milli-seconds and the solution time is a few orders of magnitude higher. That was probably the intent - changing the limit to `0.01` fixes it for me. 

For me the output of the optimization now is:
```
        message: Optimization terminated successfully. (HiGHS Status 7: Optimal)
        success: True
         status: 0
            fun: -11.00000000000001
              x: [ 0.000e+00  0.000e+00 ...  0.000e+00  0.000e+00]
 mip_node_count: 2715
 mip_dual_bound: -11.00000000000001
        mip_gap: 0.0
```

A second potential problem I see is that the timeout limit is set to `pytest.mark.timeout(360)` - that seems very high compared to the test time limit of `10`. If it really can be that high, I think the test should be marked as `xslow`.

I think this test needs a bit of restructuring:
- the timeout part should be set to a very low time limit, like `0.1`. And then only assert that a somewhat reasonable solution is returned, but not with `tol=1e-8`.
- the node-limit part needs either a shorter timeout or marked as `xslow`. 
Cc @mdhaber since I noticed your comment in another PR about looking at this test

Commit message: MAINT: optimize: fix test_milp_timeout

Patch to review:
diff --git a/scipy/optimize/tests/test_milp.py b/scipy/optimize/tests/test_milp.py
index 59f42bff1bdb..f3fe93ba4239 100644
--- a/scipy/optimize/tests/test_milp.py
+++ b/scipy/optimize/tests/test_milp.py
@@ -295,9 +295,7 @@ def test_infeasible_prob_16609():
 
 @pytest.mark.skipif(np.intp(0).itemsize < 8,
                     reason="Unhandled 32-bit GCC FP bug")
-@pytest.mark.slow
-@pytest.mark.timeout(360)
-@pytest.mark.parametrize(["options", "msg"], [({"time_limit": 10}, _msg_time),
+@pytest.mark.parametrize(["options", "msg"], [({"time_limit": 0.1}, _msg_time),
                                               ({"node_limit": 1}, _msg_iter)])
 def test_milp_timeout_16545(options, msg):
     # Ensure solution is not thrown away if MILP solver times out


Code review comments:
diff_hunk: @@ -295,9 +295,7 @@ def test_infeasible_prob_16609():
 
 @pytest.mark.skipif(np.intp(0).itemsize < 8,
                     reason="Unhandled 32-bit GCC FP bug")
-@pytest.mark.slow
-@pytest.mark.timeout(360)
-@pytest.mark.parametrize(["options", "msg"], [({"time_limit": 10}, _msg_time),
+@pytest.mark.parametrize(["options", "msg"], [({"time_limit": 0.1}, _msg_time),
path: scipy/optimize/tests/test_milp.py
text: @author:
```suggestion
@user1.mark.slow
@user1.mark.parametrize(["options", "msg"], [({"time_limit": 0.1}, _msg_time),
```