Show time taken in GitHub annotation

Author: user202729

src/sage/doctest/forker.py

@@ -1235,7 +1235,7 @@ def compile_and_execute(self, example, compiler, globs):
             example.total_state = self.running_global_digest.hexdigest()
             example.doctest_state = self.running_doctest_digest.hexdigest()
 
-    def _failure_header(self, test, example, message='Failed example:'):
+    def _failure_header(self, test, example, message='Failed example:', extra=None):
         """
         We strip out ``sage:`` prompts, so we override
         :meth:`doctest.DocTestRunner._failure_header` for better
@@ -1247,6 +1247,14 @@ def _failure_header(self, test, example, message='Failed example:'):
 
         - ``example`` -- a :class:`doctest.Example` instance in ``test``
 
+        - ``message`` -- a message to be shown. Must not have a newline
+
+        - ``extra`` -- an extra message to be shown in GitHub annotation
+
+        Note that ``message`` and ``extra`` are not accepted by
+        :meth:`doctest.DocTestRunner._failure_header`, as such by Liskov
+        substitution principle this method must be callable without passing those.
+
         OUTPUT: string used for reporting that the given example failed
 
         EXAMPLES::
@@ -1310,6 +1318,8 @@ def _failure_header(self, test, example, message='Failed example:'):
                     message += ' [failed in baseline]'
                 else:
                     command = f'::error title={message}'
+                if extra:
+                    message += f': {extra}'
                 if extra := getattr(example, 'extra', None):
                     message += f': {extra}'
                 if test.filename:
@@ -1610,12 +1620,12 @@ def report_overtime(self, out, test, example, got, *, check_timer=None):
             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 %.2fs cpu, %.2fs wall\nCheck ran for %.2fs cpu, %.2fs wall\n'
-             % (example.cputime,
-                example.walltime,
-                check_timer.cputime,
-                check_timer.walltime)))
+        time_info = ('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))
+        out(self._failure_header(test, example, 'Warning: slow doctest:', time_info) + time_info)
 
     def report_unexpected_exception(self, out, test, example, exc_info):
         r"""

src/sage/doctest/test.py

@@ -47,6 +47,42 @@
     ...
     0
 
+Check slow doctest warnings are correctly raised::
+
+    sage: subprocess.call(["sage", "-t", "--warn-long",     # long time
+    ....:       "--random-seed=0", "--optional=sage", "sleep2.rst"], **kwds)
+    Running doctests...
+    Doctesting 1 file.
+    sage -t --warn-long --random-seed=0 sleep2.rst
+    **********************************************************************
+    File "sleep2.rst", line 4, in sage.doctest.tests.sleep2
+    Warning: slow doctest:
+        while walltime(t) < 2: pass
+    Test ran for ...s cpu, ...s wall
+    Check ran for ...s cpu, ...s wall
+        [2 tests, ...s wall]
+    ----------------------------------------------------------------------
+    All tests passed!
+    ----------------------------------------------------------------------
+    ...
+    0
+    sage: subprocess.call(["sage", "-t", "--format=github", "--warn-long",     # long time
+    ....:       "--random-seed=0", "--optional=sage", "sleep2.rst"], **kwds)
+    Running doctests...
+    Doctesting 1 file.
+    sage -t --warn-long --random-seed=0 sleep2.rst
+    **********************************************************************
+    ::warning title=Warning: slow doctest:,file=sleep2.rst,line=4::slow doctest:: Test ran for ...s cpu, ...s wall%0ACheck ran for ...s cpu, ...s wall%0A
+        while walltime(t) < 2: pass
+    Test ran for ...s cpu, ...s wall
+    Check ran for ...s cpu, ...s wall
+        [2 tests, ...s wall]
+    ----------------------------------------------------------------------
+    All tests passed!
+    ----------------------------------------------------------------------
+    ...
+    0
+
 Check handling of tolerances::
 
     sage: subprocess.call(["sage", "-t", "--warn-long", "0",    # long time

src/sage/doctest/tests/sleep2.rst

@@ -0,0 +1,4 @@
+Test raising slow doctest warning (cputime instead of walltime is checked so we need busy loop)::
+
+    sage: t = walltime()
+    sage: while walltime(t) < 2: pass