Add per-test timeouts to lit

[jroelofs]

Summary

This is different than the option '--max-time', which limits total testing time.

[jroelofs]

lit/Test.py

222 ↗

(On Diff #17095)

Not sure this is the right place for this. Is there somewhere better it belongs?

[jroelofs]

lit/util.py

170 ↗

(On Diff #17095)

Something here apparently doesn't work. Foolishly, I had only tested it with timeout=0. Currently debugging.

[• ddunbar]

I would love to have this feature, so +1 on that.

I would prefer that it not introduce a new failure code though, and just
use FAIL with some extra message output.

It might be worth considering whether or not we should run the subprocesses
in their own process group if this is enabled, so that we can kill the
entire process group. I'm not sure if there is any downside to that, and I
would like to guarantee that if we have timeouts we never accidentally
leave a stray runaway subprocess, which might otherwise bog down a CI setup.

It looks like you are doing some more work on this so I will hold further
review until then.

• Daniel

[jroelofs]

Now with a version that actually works....

[jroelofs]

Here's a version of it with the TIMEOUT result stuff removed.

I'm not sure how to grab the output that happens before a timeout is reached.

[jroelofs]

Good point about the subprocess group thing. I'm not sure how to do that portably though... looks like it's only supported on unixes: https://docs.python.org/2/library/os.html

[jroelofs]

utils/lit/lit/run.py

179 ↗

(On Diff #17106)

More specifically, I mean, how do I grab the rest of the output that happened before the timeout here?

[• ddunbar]

In addition to the inline comments, could you include some tests that exercise this code?

utils/lit/lit/Test.py

221 ↗

(On Diff #17106)

I'd rather just change executeCommand to not need this than have it added here.

utils/lit/lit/main.py

212

Can we just spell this "--timeout", it's pretty obvious. If you were worried about the conflict with --max-time I'd rather rename that one to --max-testing-time or something similar, as its not a commonly used option (and I wonder if anyone other than me ever uses it). :)

utils/lit/lit/util.py

168

Can this code be factored out into a helper class? Then you wouldn't need to use the hack of wrapping timed_out in a list just so you can modify it.

170

Technically, you shouldn't need to do this, and it is probably a good safety check *not to*.

If you kill the process, then the p.wait() below should return the status showing that the process was terminated (and if it hangs, there is a problem).

[jroelofs]

Some refactorings as @ddunbar suggested.

[jroelofs]

utils/lit/lit/main.py

212

sounds good

utils/lit/lit/util.py

156

thanks for the suggestion... I like this a lot more than what I had before.

[• ddunbar]

Looks good, some nits inline. I would like to see a test or two before this goes in, though.

utils/lit/lit/util.py

11

This import isn't needed anymore.

156

Can this be lifted to the top-level of this file just to avoid the break in the code?

160

I would prefer if this class assumed timeout was non-None and the caller assumed the responsibility of handling the optionality of timeout (and just didn't create an instance)...

With this change the watchdog implementation gets a tad simpler.

161

This might be more readable as a regular method on the class instead of a nested function.

166

Sic.

171

This is currently broken, this should be self.timer, but with the change above there should only be a single assignment anyway.

178

There isn't a good reason to use a getter method here, clients can just use the property directly.

186

I'd add a newline (or two) at the start of this string, as there isn't much guarantee the existing stderr data has one.

[jroelofs]

Address more of ddunbar's comments, including adding some tests.

(doing this over email because phabricator is in the middle of some maintenance)

Jon

• lit_timeouts.diff57 KBDownload

[jroelofs]

Woo, phab is back up. Uploading the patch from the email.

[jroelofs]

ping

[jroelofs]

ping

[jroelofs]

@ddunbar, 3.6 branch is coming very soon (tomorrow?)... any chance we can get this rolling in time for that? Are there any more changes you'd like to see in this patch?

[jroelofs]

ping

[• ddunbar]

Hi Jonathan,

Thanks, this looks a lot better. I've noticed two more potential problems:

1. Watchdog.watch() has an unlikely race where the timer may have already

fired -- it should handle this case by just killing the new proc
immediately I would guess.

2. I tried your test test suite with execute_external=True, and it didn't

work for me. Does this work for you? I looked into it a little bit, and it
seems like the .communicate() method isn't returning in this case, even
though the subprocess does get killed. I haven't looked more than that...

• Daniel

[jroelofs]

Rebased.

@ddunbar I'm not sure I understand either of your two comments there. I think the first should already be handled, and the second seems to do the right thing for me when I use --timeout 1 --param=execute_external=True.

[jroelofs]

ping: @ddunbar, can you clarify your review comments please?

[jroelofs]

@danalbert any chance you can spot the race condition that @ddunbar hinted at in Watchdog.watch()? I don't see it.

[• ddunbar]

Hi Jonathan,

The race I was talking about in watch() is this:

1. Client opens Watchdog(...)
2. Watchdog.handler() fires, does nothing because self.popens is empty.
3. Client calls Watchdog.watch()
4. Now that process will never be killed by the timeout. --

For the second comment, you can't just set a param to change
execute_external, you need to change it in the test suites lit.cfg file. If
you can't reproduce with that I am not sure...

• Daniel

[jroelofs]

Ah, I see it now. Thanks. I'll re-work that part of Watchdog's interface.

[jroelofs]

Fixed the Watchdog race.

Can't reproduce the other issue @ddunbar mentioned.

[jroelofs]

re-upload with more context

[EricWF]

Misc comments. More to come.

utils/lit/lit/util.py

19

Why not start the timer when watch(...) is called for the first time? It seems like some code takes steps between creating the Watchdog and the call to watch(...). Those steps may unfairly count against the test timeout.

31

What thread of execution does Threading.timer execute this function in? I think we would need to add a lock to Watchdog if the handler runs in a separate thread.

45

How can self.timer be None?

200

How does executeCommand communicate to the caller that a timeout has occurred?

[jroelofs]

utils/lit/lit/TestRunner.py

308

Here too.

utils/lit/lit/util.py

19

sounds reasonable.

31

Good point.

I think the timer executes its action in the "other" thread (i.e. not the one that create the timer).

45

oops... leftover crud.

200

Some text about it is added to 'err' and returned. Because the timeout happened, the exitcode should be nonzero too. See below, line ~216. Also in executeScriptInternal.

[jroelofs]

address @EricWF's review comments.

[EricWF]

Leading question: If a shell command guarded by a Watchdog exits scope via an exception should Watchdog.cancel() be called? I think the Watchdog should provide a factory function that can be used in a with statement. The definition would looks something like this:

@contextmanager
def createWatchdog(timeout, popen=None):
    wg = Watchdog(timeout)
    if popen is not None:
      wg.watch(popen)
    yield wg
    wg.cancel()

I think the usage pattern for Watchdog should be:

p = subprocess.Popen(cmd)
with createWatchdog(timeout, p) as wg:
    out,err = p.communicate()
    exitCode = p.wait()

What do you think?

utils/lit/lit/TestRunner.py

294

Should this call to cancel be exception safe?

utils/lit/lit/util.py

35

I'm not sure if this matters, but I want to clarify what is considered a "timeout failure". For example, what if the timers invokes the handler but every open process has already finished? Should this be considered a timeout?

226

Should this call to cancel be exception safe?

[EricWF]

Leading question: If a shell command guarded by a Watchdog exits scope via an exception should Watchdog.cancel() be called? I think the Watchdog should provide a factory function that can be used in a with statement. The definition would looks something like this:

@contextmanager
def createWatchdog(timeout, popen=None):
    wg = Watchdog(timeout)
    if popen is not None:
      wg.watch(popen)
    yield wg
    wg.cancel()

I think the usage pattern for Watchdog should be:

p = subprocess.Popen(cmd)
with createWatchdog(timeout, p) as wg:
    out,err = p.communicate()
    exitCode = p.wait()

What do you think?

[jroelofs]

Leading question: If a shell command guarded by a Watchdog exits scope via an exception should Watchdog.cancel() be called?

I think in this case, the watchdog should kill all the processes it was watching.

I think the Watchdog should provide a factory function that can be used in a with statement.

Oooh, I like it.

utils/lit/lit/util.py

35

I consider a "timeout failure" to happen when the timer runs out before cancel() is called, regardless of whether the handler had to kill anything.

226

'exception safe' in what sense... do you expect the timer cancellation to throw?

or did you mean 'thread safe'?

[jroelofs]

Re-work Watchdog to support being used as a context manager.

[jroelofs]

delete dead code

[jroelofs]

ping.

@EricWF I don't remember what we last discussed about this... any more thoughts on it?

[EricWF]

Other than the inline comment this LGTM but I'll let @ddunbar give it the thumbs up.

utils/lit/lit/util.py

83

It is incorrect to re-raise the passed in exception.
https://docs.python.org/2/reference/datamodel.html#object.__exit__

[jroelofs]

Addressed the bug @EricWF pointed out.

[jroelofs]

ping

[jroelofs]

ping

[jroelofs]

ping

[• ddunbar]

Hi Jonathan,

When I try your patch on OS X, the test suite just hangs. Unfortunately I
don't have much time to investigate...

• Daniel

[jroelofs]

I investigate a little bit, and I believe what happens is that executeCommand() is hanging in p.communicate(), because the file descriptors haven't necessarily been closed. It did look like I could fix this by explicitly forcing a close on the file descriptors in _safely_kill(), e.g.:

os.close(popen.stdout.fileno())
os.close(popen.stderr.fileno())

but I'm not confident that is reliable.

How are you running the testsuite? I've been copy-pasting the command that the makefile runs, and adding --timeout=1 to it.

Getting the kind of behavior right is tricky, esp. while trying to be cross platform, and getting it right in Python where it isn't obvious what layers like subprocess() are doing makes me nervous. Also, I know there are some gotchas here on Windows that I would want to know are covered. Do you have access to all three major platforms to test this logic on?

Tested on Darwin14, and Ubuntu10.04... Seems to work there for me without closing the FDs. I don't have a windows box to check this on.

(Python is 2.7.9 on the Darwin machine, and 2.7.3 on the Ubuntu machine.)

Also, note that kill() will deadlock if it is ever called since both it and _handler() try to take the lock. In this example, it means that if I Ctrl-C lit after it hangs in the above then it will deadlock in the context manager exit function.

This revision fixes the deadlock on kill(). Ctrl-C seems to DTRT.

[• ddunbar]

I was just running the top-level suite, with lit -sv tests.

However, I was able to reproduce the deadlock I saw by just adding this to

util.py:

+if name == 'main':
+ print 'running watchdog test.'
+ executeCommand(['/bin/bash',
+
'/Volumes/Data/ddunbar/llvm/utils/lit/tests/Inputs/timeout/Output/infloop.py.script'],
+ None, None, 0.1)

+ raise SystemExit

This was with Python 2.7.6, which might matter.

• Daniel

[jroelofs]

Sorry for the diff spam.

utils/lit/lit/util.py

37

I don't know enough about python implementation details to know if this is 'correct' cross-platform-wise, but it appears to work on Darwin, Linux, and Cygwin on Windows.

I got ahold of a Cygwin+Windows machine and was able to test your deadlock reproducer on it with this patch. I don't have a full development environment on that machine, so I can't run all the other tests that need FileCheck, nor the full llvm testsuite, but this looks promising.

utils/lit/lit/LitConfig.py

     def __init__(self, progname, path, quiet,
                  useValgrind, valgrindLeakCheck, valgrindArgs,
                  noExecute, debug, isWindows,
-                 params, config_prefix = None):
+                 params, config_prefix = None, timeout = None):
         # The name of the test runner.
         self.progname = progname
         # The items to add to the PATH environment variable.

                 self.valgrindArgs.append('--leak-check=no')
             self.valgrindArgs.extend(self.valgrindUserArgs)
 
+        self.timeout = timeout
 
     def load_config(self, config, path):
         """load_config(config, path) - Load a config object from an alternate

utils/lit/lit/TestRunner.py

         self.cwd = cwd
         self.env = env
 
-def executeShCmd(cmd, shenv, results):
+def executeShCmd(cmd, shenv, results, watchdog=None):
     if isinstance(cmd, ShUtil.Seq):
         if cmd.op == ';':
-            res = executeShCmd(cmd.lhs, shenv, results)
-            return executeShCmd(cmd.rhs, shenv, results)
+            res = executeShCmd(cmd.lhs, shenv, results, watchdog)
+            return executeShCmd(cmd.rhs, shenv, results, watchdog)
 
         if cmd.op == '&':
             raise InternalShellError(cmd,"unsupported shell operator: '&'")
 
         if cmd.op == '||':
-            res = executeShCmd(cmd.lhs, shenv, results)
+            res = executeShCmd(cmd.lhs, shenv, results, watchdog)
             if res != 0:
-                res = executeShCmd(cmd.rhs, shenv, results)
+                res = executeShCmd(cmd.rhs, shenv, results, watchdog)
             return res
 
         if cmd.op == '&&':
-            res = executeShCmd(cmd.lhs, shenv, results)
+            res = executeShCmd(cmd.lhs, shenv, results, watchdog)
             if res is None:
                 return res
 
             if res == 0:
-                res = executeShCmd(cmd.rhs, shenv, results)
+                res = executeShCmd(cmd.rhs, shenv, results, watchdog)
             return res
 
         raise ValueError('Unknown shell command: %r' % cmd.op)

                     args[i] = f.name
 
         try:
-            procs.append(subprocess.Popen(args, cwd=shenv.cwd,
-                                          executable = executable,
-                                          stdin = stdin,
-                                          stdout = stdout,
-                                          stderr = stderr,
-                                          env = shenv.env,
-                                          close_fds = kUseCloseFDs))
+            p = subprocess.Popen(args, cwd=shenv.cwd,
+                                 close_fds = kUseCloseFDs)
+            procs.append(p)
+            if watchdog is not None:
+                watchdog.watch(p)
         except OSError as e:
             raise InternalShellError(j, 'Could not create process due to {}'.format(e))
 

         cmd = ShUtil.Seq(cmd, '&&', c)
 
     results = []
+    wd = None
     try:
+        if litConfig.timeout is not None:
+            wd = lit.util.Watchdog(litConfig.timeout)
         shenv = ShellEnvironment(cwd, test.config.environment)
-        exitCode = executeShCmd(cmd, shenv, results)
+        exitCode = executeShCmd(cmd, shenv, results, wd)
+        if wd is not None:
+            wd.cancel()
     except InternalShellError:
         e = sys.exc_info()[1]
         exitCode = 127

         out += 'Command %d Output:\n%s\n\n' % (i, cmd_out)
         out += 'Command %d Stderr:\n%s\n\n' % (i, cmd_err)
 
+    if wd is not None and wd.timed_out:
+        out += "\n\nTimed out after %.2f seconds" % (litConfig.timeout)
+
     return out, err, exitCode
 
 def executeScript(test, litConfig, tmpBase, commands, cwd):

             command = litConfig.valgrindArgs + command
 
     return lit.util.executeCommand(command, cwd=cwd,
-                                   env=test.config.environment)
+                                   env=test.config.environment,
+                                   timeout=litConfig.timeout)
 
 def parseIntegratedTestScriptCommands(source_path):
     """

utils/lit/lit/formats/base.py

         else:
             cmd.append(test.getSourcePath())
 
-        out, err, exitCode = lit.util.executeCommand(cmd)
+        out, err, exitCode = lit.util.executeCommand(cmd, timeout=litConfig.timeout)
 
         diags = out + err
         if not exitCode and not diags.strip():

utils/lit/lit/main.py

     group.add_option("", "--max-time", dest="maxTime", metavar="N",
                      help="Maximum time to spend testing (in seconds)",
                      action="store", type=float, default=None)
+    group.add_option("", "--timeout", dest="timeout", metavar="N",
+                     help="Maximum time to spend in any given test (in seconds)",
+                     action="store", type=float, default=None)
     group.add_option("", "--shuffle", dest="shuffle",
                      help="Run tests in random order",
                      action="store_true", default=False)

         debug = opts.debug,
         isWindows = isWindows,
         params = userParams,
-        config_prefix = opts.configPrefix)
+        config_prefix = opts.configPrefix,
+        timeout = opts.timeout)
 
     # Perform test discovery.
     run = lit.run.Run(litConfig,

utils/lit/lit/util.py

 import signal
 import subprocess
 import sys
+import threading
 
+class Watchdog(object):
+    """
+    Watches a Popen call, and kills it after a timeout.
+    """
+    def __init__(self, timeout):
+        self.popens = []
+        self.timed_out = False
+        self.timer = threading.Timer(timeout, self.handler)
+        self.timer.start()
+
+    def _safely_kill(self, popen):
+        if popen.poll() is None:
+            try:
+                popen.kill()
+            except OSError, e:
+                # The popen terminated or was killed by something else between
+                # the test above and when kill was called... either way we got
+                # what we wanted.
+                pass
+
+    def handler(self):
+        self.timed_out = True
+        for popen in self.popens:
+            self._safely_kill(popen)
+
+    def watch(self, popen):
+        self.popens.append(popen)
+
+        # Take care of the race condition where the timer timed out before the
+        # popen was added to the list.
+        if self.timed_out:
+            self._safely_kill(popen)
+
+    def cancel(self):
+        if self.timer is not None:
+            self.timer.cancel()
+
+
 def to_bytes(str):
     # Encode to UTF-8 to get binary data.
     return str.encode('utf-8')

 # Close extra file handles on UNIX (on Windows this cannot be done while
 # also redirecting input).
 kUseCloseFDs = not (platform.system() == 'Windows')
-def executeCommand(command, cwd=None, env=None):
+def executeCommand(command, cwd=None, env=None, timeout=None):
     p = subprocess.Popen(command, cwd=cwd,
                          stdin=subprocess.PIPE,
                          stdout=subprocess.PIPE,
                          stderr=subprocess.PIPE,
                          env=env, close_fds=kUseCloseFDs)
+
+    if timeout is not None:
+        wd = Watchdog(timeout)
+        wd.watch(p)
+
     out,err = p.communicate()
     exitCode = p.wait()
 
+    if timeout is not None:
+        wd.cancel()
+        if wd.timed_out:
+            err += "\n\nTimed out after %.2f seconds" % (timeout)
+
     # Detect Ctrl-C in subprocess.
     if exitCode == -signal.SIGINT:
         raise KeyboardInterrupt

utils/lit/tests/Inputs/timeout/infloop.py

+# RUN: %{python} %s
+# XFAIL: *
+
+import sys
+
+print "infinite loop"
+while True:
+    pass

utils/lit/tests/Inputs/timeout/lit.cfg

+# -*- Python -*-
+
+import os
+import sys
+
+import lit.formats
+
+config.name = 'timeout'
+config.test_format = lit.formats.ShTest(execute_external=False)
+config.suffixes = ['.py']
+config.test_source_root = os.path.dirname(__file__)
+config.test_exec_root = config.test_source_root
+config.target_triple = '(unused)'
+src_root = os.path.join(config.test_source_root, '..')
+config.environment['PYTHONPATH'] = src_root
+config.substitutions.append(('%{python}', sys.executable))

utils/lit/tests/Inputs/timeout/short.py

+# RUN: %{python} %s
+
+import sys
+
+print "short program"

utils/lit/tests/timeout.py

+# RUN: %{lit} \
+# RUN: %{inputs}/timeout/infloop.py \
+# RUN: %{inputs}/timeout/short.py \
+# RUN:   -j 1 -v --debug --timeout 0.1 > %t.out 2> %t.err
+# RUN: FileCheck --check-prefix=CHECK-OUT < %t.out %s
+#
+
+# CHECK-OUT: XFAIL: timeout :: infloop.py
+# CHECK-OUT: PASS: timeout :: short.py