Flaky ensure_interruptible_after() tests

[orlitzky]

Example (from CI):

Error: Failed example:: Exception raised:
cysignals.signals.AlarmInterrupt

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/share/miniconda/envs/sage-dev/lib/python3.11/site-packages/sage/doctest/forker.py", line 733, in _run
    self.compile_and_execute(example, compiler, test.globs)
  File "/usr/share/miniconda/envs/sage-dev/lib/python3.11/site-packages/sage/doctest/forker.py", line 1157, in compile_and_execute
    exec(compiled, globs)
  File "<doctest sage.matrix.matrix2.Matrix._charpoly_df[19]>", line 1, in <module>
    with ensure_interruptible_after(Integer(1)): m.charpoly()
  File "/usr/share/miniconda/envs/sage-dev/lib/python3.11/contextlib.py", line 158, in __exit__
    self.gen.throw(typ, value, traceback)
  File "/usr/share/miniconda/envs/sage-dev/lib/python3.11/site-packages/sage/doctest/util.py", line 904, in ensure_interruptible_after
    raise RuntimeError(
RuntimeError: Function is not interruptible within 1.0000 seconds, only after 1.2124 seconds

I recently "fixed" two instances of this, and a summary of the discussion is that

1. ensure_interruptible_after() is not a priori reliable because it uses wall time. The CPU scheduler is free to put any task to sleep for any amount of time.
2. Fixing that is not so trivial; for example just switching it to CPU time is not guaranteed to help unless we have 100% accurate accounting of CPU time in all subprocesses. The old cputime() asks the subprocesses to account for their time, and some of them don't. The newer CPU timer used for --warn-long relies on psutil on non-linux platforms, but psutil is standard only in the sage distro and is not a dependency of the sage library. We would also need to adjust the timing based on how fast the CPU is, or pad the numbers.
3. In the meantime, we can minimize the CI failures by ensuring that the example we're going to Ctrl-C runs for a VERY long time, and then setting the max_wait_after_interrupt to something huge, like five seconds. The tests are usually there to ensure that sig_on() and sig_off() are wrapping some C code, so if we can interrupt something that would finish in ten minutes after only, say, four seconds... it's fine.

[orlitzky]

Another:

Error: Failed example:: Got: 
cysignals.signals.AlarmInterrupt

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/runner/miniconda3/envs/sage-dev/lib/python3.12/site-packages/sage/doctest/forker.py", line 733, in _run
    self.compile_and_execute(example, compiler, test.globs)
  File "/Users/runner/miniconda3/envs/sage-dev/lib/python3.12/site-packages/sage/doctest/forker.py", line 1157, in compile_and_execute
    exec(compiled, globs)
  File "<doctest sage.doctest.util.inaccuracy_tolerance[10]>", line 1, in <module>
    with ensure_interruptible_after(Integer(1)) as data: uninterruptible_sleep(2)
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/runner/miniconda3/envs/sage-dev/lib/python3.12/contextlib.py", line 158, in __exit__
    self.gen.throw(value)
  File "/Users/runner/miniconda3/envs/sage-dev/lib/python3.12/site-packages/sage/doctest/util.py", line 904, in ensure_interruptible_after
    raise RuntimeError(
RuntimeError: Function is not interruptible within 1.0000 seconds, only after 2.0159 seconds

    with ensure_interruptible_after(1) as data: uninterruptible_sleep(2r)

Edit: the lines after that fail as a result.

Error: Failed example:: Got: {'alarm_raised': True, 'elapsed': 2.0159337520599365}
                                                                                                                                                                                                                                                                                                                                                                                                                                      
    data  # abs tol 0.01
Expected:
    {'alarm_raised': True, 'elapsed': 2.0}
Got:
    {'alarm_raised': True, 'elapsed': 2.0159337520599365}
Tolerance exceeded:
    2.0 vs 2.0159337520599365, tolerance 2e-2 > 1e-2
**********************************************************************
Error: Failed example:: Got: {'alarm_raised': True, 'elapsed': 2.0159337520599365}
                                                                                                                                                                                                                                                                                                                                                                                                                                      
    data  # abs tol 0.01
Expected:
    {'alarm_raised': True, 'elapsed': 2.0}
Got:
    {'alarm_raised': True, 'elapsed': 2.0159337520599365}
Tolerance exceeded:
    2.0 vs 2.0159337520599365, tolerance 2e-2 > 1e-2
**********************************************************************

[user202729]

it probably isn't too difficult to implement something that spawns a C thread which

• sleep for that many seconds
• start a timer (wall time suffices)
• send SIGALRM
• main thread catches the alarm, stop the timer
• check as usual.
  Although I guess timeout=4 as a stopgap measure is acceptable.

[orlitzky]

Error: Failed example:: Exception raised:
Traceback (most recent call last):
  File "/Users/runner/miniconda3/envs/sage-dev/lib/python3.11/site-packages/sage/doctest/forker.py", line 733, in _run
    self.compile_and_execute(example, compiler, test.globs)
  File "/Users/runner/miniconda3/envs/sage-dev/lib/python3.11/site-packages/sage/doctest/forker.py", line 1157, in compile_and_execute
    exec(compiled, globs)
  File "<doctest sage.sets.recursively_enumerated_set.RecursivelyEnumeratedSet_symmetric.graded_component_iterator[18]>", line 1, in <module>
    with ensure_interruptible_after(RealNumber('0.02')): next(it)
  File "/Users/runner/miniconda3/envs/sage-dev/lib/python3.11/contextlib.py", line 144, in __exit__
    next(self.gen)
  File "/Users/runner/miniconda3/envs/sage-dev/lib/python3.11/site-packages/sage/doctest/util.py", line 912, in ensure_interruptible_after
    raise RuntimeError(f"Function terminates early after {elapsed:.4f} < {seconds:.4f} seconds")
RuntimeError: Function terminates early after 0.1093 < 0.0200 seconds

    with ensure_interruptible_after(0.02): next(it)

[orlitzky]

This one uses alarm() directly but should probably be tracked here: #33230

[user202729]

I suspect the strange terminates early is actually caused by an erroneous noexcept. Example

"""

sage: cython('''
....: cpdef int f(x, long long n) noexcept:
....:     a = x
....:     for i in range(n):
....:         a += x
....:     return 1
....: cpdef int g(x, long long n, int m) noexcept:
....:     for j in range(m):
....:         f(x, n)
....: ''')
sage: class AddChecksException:
....:     def __add__(self, other):
....:         a = []
....:         del a
....:         return self
sage: from sage.doctest.util import ensure_interruptible_after
sage: with ensure_interruptible_after(0.5): f(AddChecksException(), 10**8)
sage: #with ensure_interruptible_after(0.5): g(AddChecksException(), 10**8, 2)

"""

put them into a.sage then sage -t --timeout=5 a.sage it.

If you run it in sage command-line you'll see a

Exception ignored in: '_tmp_sage_25uiafaw_tmp_f5j5rxhw_pyx_0.f'
Traceback (most recent call last):
  File "<ipython-input-45-ed96ea39db58>", line 12, in __add__
  File "signals.pyx", line 355, in cysignals.signals.python_check_interrupt
cysignals.signals.AlarmInterrupt: 

which informs you where the problem happens, unfortunately the sage doctester ignores all stdout when there's an exception.

[user202729]

actually if the process is suppressed during the 0.5 or so second it waits, it isn't an issue, the issue only happens when the process is suppressed at or right after the moment the alarm is supposed to be delivered.

Bumping 0.2 to say 0.5 might be acceptable.

[user202729]

continue the message in #40870

if a signal indeed can be dropped on the CI, that would also explain the random timeout.

(though some others are caused by __lll_lock_wait_private in malloc instead)

for reference, this test

            sage: from sage.doctest.util import ensure_interruptible_after
            sage: C = ComplexBallField(1000000)
            sage: with ensure_interruptible_after(0.1, max_wait_after_interrupt=5):
            ....:     C.integral(lambda x, _: x.cos() * x.sin(), 0, 1)

's tolerance was bumped in #40613 .

[tobiasdiez]

Here is another example, which is actually one of the doctests of ensure_interruptible_after. Maybe that helps debugging it further?

rc/bin/sage -t --warn-long 5.0 --random-seed=278045785889748596592377494798567870489 src/sage/doctest/util.py
**********************************************************************
Error: Failed example:: Got: 
cysignals.signals.AlarmInterrupt

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/runner/miniconda3/envs/sage-dev/lib/python3.12/site-packages/sage/doctest/forker.py", line 733, in _run
    self.compile_and_execute(example, compiler, test.globs)
  File "/Users/runner/miniconda3/envs/sage-dev/lib/python3.12/site-packages/sage/doctest/forker.py", line 1157, in compile_and_execute
    exec(compiled, globs)
  File "<doctest sage.doctest.util.inaccuracy_tolerance[10]>", line 1, in <module>
    with ensure_interruptible_after(Integer(1)) as data: uninterruptible_sleep(2)
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/runner/miniconda3/envs/sage-dev/lib/python3.12/contextlib.py", line 158, in __exit__
    self.gen.throw(value)
  File "/Users/runner/miniconda3/envs/sage-dev/lib/python3.12/site-packages/sage/doctest/util.py", line 897, in ensure_interruptible_after
    raise RuntimeError(
RuntimeError: Function is not interruptible within 1.0000 seconds, only after 2.0105 seconds

    with ensure_interruptible_after(1) as data: uninterruptible_sleep(2r)
Expected:
    Traceback (most recent call last):
    ...
    RuntimeError: Function is not interruptible within 1.0000 seconds, only after 2.00... seconds
Got:
    <BLANKLINE>
    cysignals.signals.AlarmInterrupt
    <BLANKLINE>
    During handling of the above exception, another exception occurred:
    <BLANKLINE>
    Traceback (most recent call last):
      File "/Users/runner/miniconda3/envs/sage-dev/lib/python3.12/site-packages/sage/doctest/forker.py", line 733, in _run
        self.compile_and_execute(example, compiler, test.globs)
      File "/Users/runner/miniconda3/envs/sage-dev/lib/python3.12/site-packages/sage/doctest/forker.py", line 1157, in compile_and_execute
        exec(compiled, globs)
      File "<doctest sage.doctest.util.inaccuracy_tolerance[10]>", line 1, in <module>
        with ensure_interruptible_after(Integer(1)) as data: uninterruptible_sleep(2)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/Users/runner/miniconda3/envs/sage-dev/lib/python3.12/contextlib.py", line 158, in __exit__
        self.gen.throw(value)
      File "/Users/runner/miniconda3/envs/sage-dev/lib/python3.12/site-packages/sage/doctest/util.py", line 897, in ensure_interruptible_after
        raise RuntimeError(
    RuntimeError: Function is not interruptible within 1.0000 seconds, only after 2.0105 seconds
**********************************************************************
Error: Failed example:: Got: {'alarm_raised': True, 'elapsed': 2.010450839996338}
                                                                                                                                                                                                                                                                                                                                                                                                                                       
    data  # abs tol 0.01
Expected:
    {'alarm_raised': True, 'elapsed': 2.0}
Got:
    {'alarm_raised': True, 'elapsed': 2.010450839996338}
Tolerance exceeded:
    2.0 vs 2.010450839996338, tolerance 2e-2 > 1e-2
**********************************************************************
Error: Failed example:: Got: {'alarm_raised': True, 'elapsed': 2.010450839996338}
                                                                                                                                                                                                                                                                                                                                                                                                                                       
    data  # abs tol 0.01
Expected:
    {'alarm_raised': True, 'elapsed': 2.0}
Got:
    {'alarm_raised': True, 'elapsed': 2.010450839996338}
Tolerance exceeded:
    2.0 vs 2.010450839996338, tolerance 2e-2 > 1e-2
**********************************************************************
1 item had failures:
   3 of  17 in sage.doctest.util.inaccuracy_tolerance
    [186 tests, 3 failures, 12.46s wall]

https://github.com/sagemath/sage/actions/runs/18258273069/job/51982624150?pr=39189#step:15:3443

[tobiasdiez]

And another one:

src/bin/sage -t --warn-long 5.0 --random-seed=48244435157528336271298950017649932731 src/sage/matrix/matrix2.pyx
**********************************************************************
Error: Failed example:: Exception raised:
cysignals.signals.AlarmInterrupt

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/runner/work/sage/sage/src/sage/doctest/forker.py", line 733, in _run
    self.compile_and_execute(example, compiler, test.globs)
  File "/home/runner/work/sage/sage/src/sage/doctest/forker.py", line 1157, in compile_and_execute
    exec(compiled, globs)
  File "<doctest sage.matrix.matrix2.Matrix._charpoly_df[19]>", line 1, in <module>
    with ensure_interruptible_after(Integer(1)): m.charpoly()
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/share/miniconda/envs/sage-dev/lib/python3.12/contextlib.py", line 158, in __exit__
    self.gen.throw(value)
  File "/home/runner/work/sage/sage/src/sage/doctest/util.py", line 897, in ensure_interruptible_after
    raise RuntimeError(
RuntimeError: Function is not interruptible within 1.0000 seconds, only after 1.2381 seconds

    with ensure_interruptible_after(1): m.charpoly()
Exception raised:
    cysignals.signals.AlarmInterrupt

    During handling of the above exception, another exception occurred:

    Traceback (most recent call last):
      File "/home/runner/work/sage/sage/src/sage/doctest/forker.py", line 733, in _run
        self.compile_and_execute(example, compiler, test.globs)
      File "/home/runner/work/sage/sage/src/sage/doctest/forker.py", line 1157, in compile_and_execute
        exec(compiled, globs)
      File "<doctest sage.matrix.matrix2.Matrix._charpoly_df[19]>", line 1, in <module>
        with ensure_interruptible_after(Integer(1)): m.charpoly()
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
      File "/usr/share/miniconda/envs/sage-dev/lib/python3.12/contextlib.py", line 158, in __exit__
        self.gen.throw(value)
      File "/home/runner/work/sage/sage/src/sage/doctest/util.py", line 897, in ensure_interruptible_after
        raise RuntimeError(
    RuntimeError: Function is not interruptible within 1.0000 seconds, only after 1.2381 seconds
**********************************************************************
1 item had failures:
   1 of  21 in sage.matrix.matrix2.Matrix._charpoly_df
    [3227 tests, 1 failure, 14.90s wall]

[user202729]

we pretty much just assume the 2.00 → 2.01 is just "CI machine randomly slow". I "workaround" that one by just increase tolerance from 1e-2 to 1e-1 in #40980

the second one is this

        Test that the function is interruptible::

            sage: m = matrix.random(RR, 128)
            sage: from sage.doctest.util import ensure_interruptible_after
            sage: with ensure_interruptible_after(1): m.charpoly()

looks like legitimate bug? 0.23s is a lot.

but as far as I can see there are enough sig_check() at places already… wait… the second loop (which may be up to $O(n^2)$ ) doesn't have sig_check(). → #40983