Skip to content

Commit

Permalink
src/sage/doctest: use CPU time for --warn-long
Browse files Browse the repository at this point in the history
Our --warn-long flag used during testing currently takes "wall time"
as its argument. This is somewhat nice from a user perspective, since
a normal user is quite likely to know what what wall time is, but it's
also a bit nonsensical given the purpose of the flag. The flag's
intent is to warn developers about tests that take too long, so
whether or not it triggers should not depend on the developer's
machine, or what else he's doing while the tests are running -- both
of which do affect the wall time.

CPU time provides a more reliable measurement. (In fact, when no value
for --wall-time was given, we were already using a heuristic to mimic
CPU time.) This commit changes the --warn-long flag to use CPU time
instead of wall time, obviating the need for the heuristic.

Issue: sagemathGH-32981
  • Loading branch information
orlitzky committed Oct 8, 2024
1 parent b0f09d9 commit 60fb163
Show file tree
Hide file tree
Showing 2 changed files with 20 additions and 24 deletions.
24 changes: 10 additions & 14 deletions src/sage/doctest/control.py
Original file line number Diff line number Diff line change
Expand Up @@ -588,36 +588,32 @@ 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, for all tests, is 60 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

self.options.warn_long = 60.0

def second_on_modern_computer(self):
"""
Expand Down
20 changes: 10 additions & 10 deletions src/sage/doctest/forker.py
Original file line number Diff line number Diff line change
Expand Up @@ -729,7 +729,7 @@ def compiler(example):
finally:
if self.debugger is not None:
self.debugger.set_continue() # ==== Example Finished ====
check_starttime = walltime()
check_timer = Timer().start()
got = self._fakeout.getvalue()

outcome = FAILURE # guilty until proved innocent or insane
Expand Down Expand Up @@ -803,22 +803,22 @@ def compiler(example):
f"and it succeeded (raised an exception as expected).")
outcome = SUCCESS

check_duration = walltime(check_starttime)
self.total_walltime += example.walltime + check_duration
check_timer.stop()
self.total_walltime += example.walltime + check_timer.walltime

# Report the outcome.
if example.warnings:
for warning in example.warnings:
out(self._failure_header(test, example, f'Warning: {warning}'))
if outcome is SUCCESS:
if self.options.warn_long > 0 and example.walltime + check_duration > self.options.warn_long:
if self.options.warn_long > 0 and example.cputime + check_timer.cputime > self.options.warn_long:
self.report_overtime(out, test, example, got,
check_duration=check_duration)
check_duration=check_timer.cputime)
elif example.warnings:
pass
elif not quiet:
self.report_success(out, test, example, got,
check_duration=check_duration)
check_duration=check_timer.cputime)
elif probed_tags:
pass
elif outcome is FAILURE:
Expand Down Expand Up @@ -1528,17 +1528,17 @@ def report_overtime(self, out, test, example, got, *, check_duration=0):
sage: FDS = FileDocTestSource(filename, DD)
sage: doctests, extras = FDS.create_doctests(globals())
sage: ex = doctests[0].examples[0]
sage: ex.walltime = 1.23r
sage: ex.cputime = 1.23
sage: DTR.report_overtime(sys.stdout.write, doctests[0], ex, 'BAD ANSWER\n', check_duration=2.34r)
**********************************************************************
File ".../sage/doctest/forker.py", line 12, in sage.doctest.forker
Warning, slow doctest:
doctest_var = 42; doctest_var^2
Test ran for 1.23 s, check ran for 2.34 s
Test ran for 1.23 cpu seconds, check ran for 2.34 cpu seconds
"""
out(self._failure_header(test, example, 'Warning, slow doctest:') +
('Test ran for %.2f s, check ran for %.2f s\n'
% (example.walltime, check_duration)))
('Test ran for %.2f cpu seconds, check ran for %.2f cpu seconds\n'
% (example.cputime, check_duration)))

def report_unexpected_exception(self, out, test, example, exc_info):
r"""
Expand Down

0 comments on commit 60fb163

Please sign in to comment.