Skip to content

Commit

Permalink
src/sage/doctest/forker.py: report both cpu/wall times for long tests
Browse files Browse the repository at this point in the history
We need to report the CPU time for tests that run afoul of
--warn-long, because --warn-long is now specified in CPU time. But, we
are still reporting the wall time in several places, such as the
per-file summary. So to keep things as consistent as possible, we
should report the wall time for --warn-long failures as well. This
changes the output of a too-long test from e.g.

  Test ran for 1.23 cpu seconds, check ran for 2.34 cpu seconds

to,

  Test ran for 1.23s cpu, 2.50s wall
  Check ran for 2.34s cpu, 3.12s wall

Issue: sagemathGH-32981
  • Loading branch information
orlitzky committed Oct 8, 2024
1 parent 48b249d commit 1e2e24f
Showing 1 changed file with 36 additions and 19 deletions.
55 changes: 36 additions & 19 deletions src/sage/doctest/forker.py
Original file line number Diff line number Diff line change
Expand Up @@ -813,12 +813,12 @@ def compiler(example):
if outcome is SUCCESS:
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_timer.cputime)
check_timer=check_timer)
elif example.warnings:
pass
elif not quiet:
self.report_success(out, test, example, got,
check_duration=check_timer.cputime)
check_timer=check_timer)
elif probed_tags:
pass
elif outcome is FAILURE:
Expand Down Expand Up @@ -1326,7 +1326,7 @@ def report_start(self, out, test, example):
start_txt += 'Expecting nothing\n'
out(start_txt)

def report_success(self, out, test, example, got, *, check_duration=0):
def report_success(self, out, test, example, got, *, check_timer=None):
"""
Called when an example succeeds.
Expand All @@ -1340,8 +1340,9 @@ def report_success(self, out, test, example, got, *, check_duration=0):
- ``got`` -- string; the result of running ``example``
- ``check_duration`` -- number (default: ``0``); time spent for checking
the test output
- ``check_timer`` -- a :class:`sage.doctest.util.Timer` (default:
``None``) that measures the time spent checking whether or not
the output was correct
OUTPUT: prints a report to ``out``; if in debugging mode, starts an
IPython prompt at the point of the failure
Expand All @@ -1352,20 +1353,27 @@ def report_success(self, out, test, example, got, *, check_duration=0):
sage: from sage.doctest.forker import SageDocTestRunner
sage: from sage.doctest.sources import FileDocTestSource
sage: from sage.doctest.control import DocTestDefaults; DD = DocTestDefaults()
sage: from sage.misc.timing import walltime
sage: from sage.doctest.util import Timer
sage: import doctest, sys, os
sage: DTR = SageDocTestRunner(SageOutputChecker(), verbose=True, sage_options=DD, optionflags=doctest.NORMALIZE_WHITESPACE|doctest.ELLIPSIS)
sage: filename = sage.doctest.forker.__file__
sage: FDS = FileDocTestSource(filename, DD)
sage: doctests, extras = FDS.create_doctests(globals())
sage: ex = doctests[0].examples[0]
sage: ex.cputime = 0.0r
sage: DTR.report_success(sys.stdout.write, doctests[0], ex, '1764')
ok [0.00 s]
sage: ex.cputime = 1.01
sage: ex.walltime = 1.12
sage: check = Timer()
sage: check.cputime = 2.14
sage: check.walltime = 2.71
sage: DTR.report_success(sys.stdout.write, doctests[0], ex, '1764',
....: check_timer=check)
ok [3.83 s]
"""
# We completely replace doctest.DocTestRunner.report_success so that we can include time taken for the test
# We completely replace doctest.DocTestRunner.report_success
# so that we can include time taken for the test
if self._verbose:
out("ok [%.2f s]\n" % (example.cputime + check_duration))
out("ok [%.2f s]\n" %
(example.walltime + check_timer.walltime))

def report_failure(self, out, test, example, got, globs):
r"""
Expand Down Expand Up @@ -1495,7 +1503,7 @@ def report_failure(self, out, test, example, got, globs):
self._fakeout.start_spoofing()
return returnval

def report_overtime(self, out, test, example, got, *, check_duration=0):
def report_overtime(self, out, test, example, got, *, check_timer=None):
r"""
Called when the ``warn_long`` option flag is set and a doctest
runs longer than the specified time.
Expand All @@ -1510,8 +1518,9 @@ def report_overtime(self, out, test, example, got, *, check_duration=0):
- ``got`` -- string; the result of running ``example``
- ``check_duration`` -- number (default: ``0``); time spent for checking
the test output
- ``check_timer`` -- a :class:`sage.doctest.util.Timer` (default:
``None``) that measures the time spent checking whether or not
the output was correct
OUTPUT: prints a report to ``out``
Expand All @@ -1521,24 +1530,32 @@ def report_overtime(self, out, test, example, got, *, check_duration=0):
sage: from sage.doctest.forker import SageDocTestRunner
sage: from sage.doctest.sources import FileDocTestSource
sage: from sage.doctest.control import DocTestDefaults; DD = DocTestDefaults()
sage: from sage.misc.timing import walltime
sage: from sage.doctest.util import Timer
sage: import doctest, sys, os
sage: DTR = SageDocTestRunner(SageOutputChecker(), verbose=True, sage_options=DD, optionflags=doctest.NORMALIZE_WHITESPACE|doctest.ELLIPSIS)
sage: filename = sage.doctest.forker.__file__
sage: FDS = FileDocTestSource(filename, DD)
sage: doctests, extras = FDS.create_doctests(globals())
sage: ex = doctests[0].examples[0]
sage: ex.cputime = 1.23
sage: DTR.report_overtime(sys.stdout.write, doctests[0], ex, 'BAD ANSWER\n', check_duration=2.34r)
sage: ex.walltime = 2.50
sage: check = Timer()
sage: check.cputime = 2.34
sage: check.walltime = 3.12
sage: DTR.report_overtime(sys.stdout.write, doctests[0], ex, 'BAD ANSWER\n', check_timer=check)
**********************************************************************
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 cpu seconds, check ran for 2.34 cpu seconds
Test ran for 1.23s cpu, 2.50s wall
Check ran for 2.34s cpu, 3.12s wall
"""
out(self._failure_header(test, example, 'Warning, slow doctest:') +
('Test ran for %.2f cpu seconds, check ran for %.2f cpu seconds\n'
% (example.cputime, check_duration)))
('Test ran for %.2fs cpu, %.2fs wall\nCheck ran for %.2fs cpu, %.2fs wall\n'
% (example.cputime,
example.walltime,
check_timer.cputime,
check_timer.walltime)))

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

0 comments on commit 1e2e24f

Please sign in to comment.