From 840b7ddaf559b4b95571e0c48a85aaa3a70943df Mon Sep 17 00:00:00 2001 From: Michael Orlitzky Date: Fri, 8 Sep 2023 18:10:57 -0400 Subject: [PATCH] src/sage/doctest/util.py: cputime for pexpect interfaces on Linux/BSD After switching the doctests to report cputime instead of walltime, the running-time measurements for tests using pexpect interfaces are off because the time spent in subprocesses is not accounted for. Fixing this turns out not to be easy: the cputime() function in sage.misc.timing can try to account for them, but it is essentially asking the subprocess to compute its own cputime. This has faults: 1. Not every pexpect interface implemented (or can implement) such a method. 2. The pexpect interface needs to be in good working condition before we can ask the subprocess to do anything. That's often not the case at the end of a "sage: ..." line in a doctest. Particularly it's not true in all of the tests for low-level details of our pexpect interface itself. Instead, this commit parses /proc//stat to obtain the cputime numbers for pexpext processes. This works well with one caveat: that information is only available on Linux and BSD. Having a solution that only works on some platforms is not actually too problematic. The motivation for measuring these times in the doctest framework is that someone should notice an outrageously long test and fix or report it. So, it's enough that the measurements be accurate on only some platforms -- particularly where the CI is run. Furthermore, the information is only both missing and potentially useful for long-running pexpect tests, which are relatively rare. It would be possible to implement the same thing for macOS using its own platform-specific interface if anyone is motivated to do so. It would also make sense to use psutil to obtain this information once we have upgraded to a version of ipykernel that reintroduces it as a dependency (see GH-33772). Issue: GH-32981 --- src/sage/doctest/util.py | 70 +++++++++++++++++++++++++++++++++++++--- 1 file changed, 66 insertions(+), 4 deletions(-) diff --git a/src/sage/doctest/util.py b/src/sage/doctest/util.py index 7446373eae0..46ec16f0fe6 100644 --- a/src/sage/doctest/util.py +++ b/src/sage/doctest/util.py @@ -22,8 +22,8 @@ # https://www.gnu.org/licenses/ # **************************************************************************** -from sage.misc.timing import walltime, cputime - +from sage.misc.timing import walltime +from os import sysconf, times def count_noun(number, noun, plural=None, pad_number=False, pad_noun=False): """ @@ -103,6 +103,68 @@ class Timer: {} sage: TestSuite(Timer()).run() """ + + def _pid_cpu_seconds(self, pid): + r""" + Parse the ``/proc`` filesystem to get the cputime of the given + ``pid``. + + This also includes the times for child processes **that have + been ``wait()``ed for and terminated**. Specifically, pexpect + processes DO NOT fall into that category. + """ + with open(f"/proc/{pid}/stat", "r") as statfile: + stats = statfile.read().split() + + # man 5 proc (linux) + cputicks = sum( float(s) for s in stats[13:17] ) + + hertz = sysconf("SC_CLK_TCK") + return (cputicks / hertz) + + def _quick_cputime(self): + r""" + A fast and replacement for ``sage.misc.misc.cputime``. + + This is a "reliable" replacement (on Linux/BSD) that takes + subprocesses (particularly pexpect interfaces) into + account. The ``cputime()`` function from the ``misc`` module + can be passed ``subprocesses=True``, but this has a few + faults; mainly that it relies on each pexpect interface to + implement its own ``cputime()`` function. And most of our + pexpect interfaces either don't implement one, or implement + one in a way that requires the subprocess (being pexpected) to + be in perfect working condition -- that will often not be the + case at the end of a doctest line. + + OUTPUT: + + A float measuring the cputime in seconds of the sage process + and all its subprocesses. + """ + # Start by using os.times() to get the cputime for sage itself + # and any subprocesses that have been wait()ed for and that + # have terminated. + cputime = sum( times()[:4] ) + + # Now try to get the times for any pexpect interfaces, since + # they do not fall into the category above. + from sage.interfaces.quit import expect_objects + for s in expect_objects: + S = s() + if S and S.is_running(): + try: + cputime += self._pid_cpu_seconds(S.pid()) + except (ArithmeticError, LookupError, OSError, + TypeError, ValueError): + # This will fail anywhere but linux/BSD, but + # there's no good cross-platform way to get the + # cputimes from pexpect interfaces without + # totally mucking up the doctests. + pass + + return cputime + def start(self): """ Start the timer. @@ -115,7 +177,7 @@ def start(self): sage: Timer().start() {'cputime': ..., 'walltime': ...} """ - self.cputime = cputime() + self.cputime = self._quick_cputime() self.walltime = walltime() return self @@ -133,7 +195,7 @@ def stop(self): sage: timer.stop() {'cputime': ..., 'walltime': ...} """ - self.cputime = cputime(self.cputime) + self.cputime = self._quick_cputime() - self.cputime self.walltime = walltime(self.walltime) return self