gh-36226: Use CPU time for --warn-long
    
Finally address #32981.

Using wall time to measure which tests are "long" doesn't make much
sense. Wall time is subject to every conflating factor:

1. Faster hardware runs tests in less wall time
2. Faster compiler flags makes code that runs in less wall time
3. A busy machine will run tests slower than an unburdened one
4. Operating system priority can increase or decrease the time taken by
a process
5. etc.

Ideally, everyone would agree on how long is too long for a test to run.
Attaining that ideal is not so easy, but the first step is to
switch`--warn-long` away from using wall time and towards using CPU
time. A second phase (#33022)
will normalize the CPU time.


### Examples

#### --warn-long output

The user-facing portion of this can be tested with a low `--warn-long`
value,

```
$ sage -t --warn-long=1 src/sage/rings/qqbar.py
...
Doctesting 1 file.
sage -t --warn-long --random-
seed=309742757431591512726158538133919135994 src/sage/rings/qqbar.py
**********************************************************************
File "src/sage/rings/qqbar.py", line 511, in sage.rings.qqbar
Warning, slow doctest:
    z, = [r for r in p4.roots(QQbar, False) if r in ival]
Test ran for 1.51s cpu, 1.51s wall
Check ran for 0.00s cpu, 0.00s wall
**********************************************************************
File "src/sage/rings/qqbar.py", line 524, in sage.rings.qqbar
Warning, slow doctest:
    z2 = QQbar.polynomial_root(p4, ival)
Test ran for 1.07s cpu, 1.07s wall
Check ran for 0.00s cpu, 0.00s wall
**********************************************************************
File "src/sage/rings/qqbar.py", line 808, in
sage.rings.qqbar.AlgebraicField_common._factor_multivariate_polynomial
Warning, slow doctest:
    F = QQbar._factor_multivariate_polynomial(p)
Test ran for 2.38s cpu, 2.42s wall
Check ran for 0.00s cpu, 0.00s wall

...
```

#### pexpect accounting

Two different methods are used to account for the CPU time, one for
linux, and one for everything else. This GAP command uses pexpect and
should chew up a good bit of CPU time:

```
sage: from sage.doctest.util import Timer
sage: t = Timer()
sage: _ = t.start(); t.stop()    # no CPU time used between start/stop
{'cputime': 0.0, 'walltime': 7.605552673339844e-05}

sage: _ = t.start(); gap.eval('a:=List([0..10000],i->WordAlp("a",i));;
IsSortedList(a);'); t.stop()    # lots of CPU time used
'true'
{'cputime': 30.089999999999996, 'walltime': 36.292088747024536}
```
    
URL: #36226
Reported by: Michael Orlitzky
Reviewer(s): Gonzalo Tornaría, John H. Palmieri, Michael Orlitzky, Tobias Diez

Author: Release Manager

pkgs/sagemath-repl/MANIFEST.in

@@ -7,6 +7,12 @@ include sage/misc/sagedoc.py
 include sage/misc/sage_input.py
 include sage/misc/sage_eval.py
 
+# expect_objects from sage.interfaces.quit is needed to compute the
+# CPU time used by each doctest. We include sage.interfaces.cleaner
+# because it is conditionally imported by sage.interfaces.quit.
+include sage/interfaces/quit.py
+include sage/interfaces/cleaner.py
+
 include VERSION.txt
 
 global-exclude all__*.py

pkgs/sagemath-repl/pyproject.toml.m4

@@ -42,6 +42,7 @@ py-modules = [
 ]
 packages = [
     "sage.doctest",
+    "sage.interfaces",
     "sage.repl",
     "sage.repl.display",
     "sage.repl.ipython_kernel",

src/bin/sage

@@ -428,7 +428,7 @@ usage_advanced() {
         echo "     --initial        -- only show the first failure per block"
         echo "     --debug          -- drop into PDB after an unexpected error"
         echo "     --failed         -- only test files that failed last test"
-        echo "     --warn-long [timeout] -- warning if doctest is slow"
+        echo "     --warn-long [timeout] -- warn if tests take too much CPU time"
         echo "     --only-errors    -- only output failures, not successes"
         echo "     --gc=GC          -- control garbarge collection (ALWAYS:"
         echo "                         collect garbage before every test; NEVER:"

src/doc/en/developer/doctesting.rst

@@ -745,10 +745,10 @@ In order to run the long tests as well, do the following::
         cpu time: 25.2 seconds
         cumulative wall time: 34.7 seconds
 
-To find tests that take longer than the allowed time use the
-``--warn-long`` flag.  Without any options it will cause tests to
-print a warning if they take longer than 1.0 second. Note that this is
-a warning, not an error::
+To find tests that take longer than a specified amount of CPU time,
+use the ``--warn-long`` flag.  Without any options, it will cause a
+warning to be printed if any tests take longer than one
+cpu-second. Note that this is a warning, not an error::
 
     [roed@localhost sage]$ ./sage -t --warn-long src/sage/rings/factorint.pyx
     Running doctests with ID 2012-07-14-03-27-03-2c952ac1.
@@ -758,22 +758,22 @@ a warning, not an error::
     File "src/sage/rings/factorint.pyx", line 125, in sage.rings.factorint.base_exponent
     Failed example:
         base_exponent(-4)
-    Test ran for 4.09 s
+    Test ran for 4.09 cpu seconds
     **********************************************************************
     File "src/sage/rings/factorint.pyx", line 153, in sage.rings.factorint.factor_aurifeuillian
     Failed example:
         fa(2^6+1)
-    Test ran for 2.22 s
+    Test ran for 2.22 cpu seconds
     **********************************************************************
     File "src/sage/rings/factorint.pyx", line 155, in sage.rings.factorint.factor_aurifeuillian
     Failed example:
         fa(2^58+1)
-    Test ran for 2.22 s
+    Test ran for 2.22 cpu seconds
     **********************************************************************
     File "src/sage/rings/factorint.pyx", line 163, in sage.rings.factorint.factor_aurifeuillian
     Failed example:
         fa(2^4+1)
-    Test ran for 2.25 s
+    Test ran for 2.25 cpu seconds
     **********************************************************************
     ----------------------------------------------------------------------
     All tests passed!
@@ -792,12 +792,12 @@ You can also pass in an explicit amount of time::
     File "tests.py", line 240, in sage.rings.tests.test_random_elements
     Failed example:
         sage.rings.tests.test_random_elements(trials=1000)  # long time (5 seconds)
-    Test ran for 13.36 s
+    Test ran for 13.36 cpu seconds
     **********************************************************************
     File "tests.py", line 283, in sage.rings.tests.test_random_arith
     Failed example:
         sage.rings.tests.test_random_arith(trials=1000)   # long time (5 seconds?)
-    Test ran for 12.42 s
+    Test ran for 12.42 cpu seconds
     **********************************************************************
     ----------------------------------------------------------------------
     All tests passed!

src/sage/doctest/__main__.py

@@ -64,7 +64,7 @@ def _make_parser():
                         help="run as many doctests as possible in about 300 seconds (or the number of seconds given as an optional argument)")
     parser.add_argument("--warn-long", dest="warn_long", nargs='?',
                         type=float, default=-1.0, const=1.0, metavar="SECONDS",
-                        help="warn if tests take more time than SECONDS")
+                        help="warn if tests take more CPU time than SECONDS")
     # By default, include all tests marked 'sagemath_doc_html' -- see
     # https://github.com/sagemath/sage/issues/25345 and
     # https://github.com/sagemath/sage/issues/26110:

src/sage/doctest/control.py

@@ -588,36 +588,38 @@ def __del__(self):
 
     def _init_warn_long(self):
         """
-        Pick a suitable default for the ``--warn-long`` option if not specified.
+        Pick a suitable default for the ``--warn-long`` option if not
+        specified.
 
         It is desirable to have all tests (even ``# long`` ones)
         finish in less than about 5 seconds. Longer tests typically
         don't add coverage, they just make testing slow.
 
-        The default used here is 60 seconds on a modern computer. It
-        should eventually be lowered to 5 seconds, but its best to
-        boil the frog slowly.
+        The default used here is 5 seconds, unless `--long` was used,
+        in which case it is 30 seconds.
 
-        The stored timings are used to adjust this limit according to
-        the machine running the tests.
+        TESTS:
 
-        EXAMPLES::
+        Ensure that the user's command-line options are not changed::
 
-            sage: from sage.doctest.control import DocTestDefaults, DocTestController
+            sage: from sage.doctest.control import (DocTestDefaults,
+            ....:                                   DocTestController)
             sage: DC = DocTestController(DocTestDefaults(), [])
             sage: DC.options.warn_long = 5.0
             sage: DC._init_warn_long()
-            sage: DC.options.warn_long    # existing command-line options are not changed
+            sage: DC.options.warn_long
             5.00000000000000
         """
         # default is -1.0
         if self.options.warn_long >= 0:     # Specified on the command line
             return
-        try:
-            self.options.warn_long = 60.0 * self.second_on_modern_computer()
-        except RuntimeError as err:
-            if not sage.doctest.DOCTEST_MODE:
-                print(err)   # No usable timing information
+
+        # The developer's guide says that even a "long time" test
+        # should ideally complete in under five seconds, so we're
+        # being rather generous here.
+        self.options.warn_long = 5.0
+        if self.options.long:
+            self.options.warn_long = 30.0
 
     def second_on_modern_computer(self):
         """
@@ -637,6 +639,9 @@ def second_on_modern_computer(self):
             sage: DC = DocTestController(DocTestDefaults(), [])
             sage: DC.second_on_modern_computer()   # not tested
         """
+        from sage.misc.superseded import deprecation
+        deprecation(32981, "this method is no longer used by the sage library and will eventually be removed")
+
         if len(self.stats) == 0:
             raise RuntimeError('no stored timings available')
         success = []
@@ -1152,7 +1157,7 @@ def run_doctests(self):
             sage: DC.run_doctests()
             Doctesting 1 file.
             sage -t .../sage/rings/homset.py
-                [... tests, ... s]
+                [... tests, ...s wall]
             ----------------------------------------------------------------------
             All tests passed!
             ----------------------------------------------------------------------
@@ -1229,7 +1234,7 @@ def cleanup(self, final=True):
             Running doctests with ID ...
             Doctesting 1 file.
             sage -t .../rings/all.py
-                [... tests, ... s]
+                [... tests, ...s wall]
             ----------------------------------------------------------------------
             All tests passed!
             ----------------------------------------------------------------------
@@ -1433,7 +1438,7 @@ def run(self):
             Running doctests with ID ...
             Doctesting 1 file.
             sage -t .../sage/sets/non_negative_integers.py
-                [... tests, ... s]
+                [... tests, ...s wall]
             ----------------------------------------------------------------------
             All tests passed!
             ----------------------------------------------------------------------
@@ -1457,7 +1462,7 @@ def run(self):
             Features to be detected: ...
             Doctesting 1 file.
             sage -t ....py
-                [0 tests, ... s]
+                [0 tests, ...s wall]
             ----------------------------------------------------------------------
             All tests passed!
             ----------------------------------------------------------------------
@@ -1483,7 +1488,7 @@ def run(self):
             Features to be detected: ...
             Doctesting 1 file.
             sage -t ....py
-                [4 tests, ... s]
+                [4 tests, ...s wall]
             ----------------------------------------------------------------------
             All tests passed!
             ----------------------------------------------------------------------
@@ -1501,7 +1506,7 @@ def run(self):
             Features to be detected: ...
             Doctesting 1 file.
             sage -t ....py
-                [4 tests, ... s]
+                [4 tests, ...s wall]
             ----------------------------------------------------------------------
             All tests passed!
             ----------------------------------------------------------------------
@@ -1519,7 +1524,7 @@ def run(self):
             Features to be detected: ...
             Doctesting 1 file.
             sage -t ....py
-                [4 tests, ... s]
+                [4 tests, ...s wall]
             ----------------------------------------------------------------------
             All tests passed!
             ----------------------------------------------------------------------
@@ -1627,7 +1632,7 @@ def run_doctests(module, options=None):
         Running doctests with ID ...
         Doctesting 1 file.
         sage -t .../sage/rings/all.py
-            [... tests, ... s]
+            [... tests, ...s wall]
         ----------------------------------------------------------------------
         All tests passed!
         ----------------------------------------------------------------------