Support for running a limited amount of browser tests in parallel

tools/testing/dart/test_runner.dart

 // Copyright (c) 2012, the Dart project authors.  Please see the AUTHORS file
 // for details. All rights reserved. Use of this source code is governed by a
 // BSD-style license that can be found in the LICENSE file.
 
 /**
  * Classes and methods for executing tests.
  *
  * This module includes:
  * - Managing parallel execution of tests, including timeout checks.
  * - Evaluating the output of each test as pass/fail/crash/timeout.
@@ skipping 536 matching lines @@
                                  timedOut,
                                  stdout,
                                  stderr,
                                  time,
                                  compilationSkipped);
   }
 
   String get result =>
       hasCrashed ? CRASH : (hasTimedOut ? TIMEOUT : (hasFailed ? FAIL : PASS));
 
-  bool get unexpectedOutput => !testCase.expectedOutcomes.contains(result);
+  bool get unexpectedOutput {

[ricow1, 2013/01/24 09:04:28]

can't we just override this in the BrowserCommandOutputImpl class instead, so
that we have the specialized functionality there?

[kustermann, 2013/01/29 08:43:32]

I got rid of this code now.

+    if (testCase.commandOutputs[testCase.commands.last] == this) {
+      // This [this] is the CommandOutput instance for the browser command
+      // (the last one)
+      return !testCase.expectedOutcomes.contains(result);
+    } else {
+      // This has to be the compilation command.
+      return exitCode != 0;

[ricow1, 2013/01/24 09:04:28]

was this wrong before?

[kustermann, 2013/01/29 08:43:32]

I'm not 100% sure. My guess:
We only used 'testCase.lastCommandOutput.unexpectedOutput' on the browser test
command. (I think RunningProcess previously made sure that all commands except
the last one have 'exitCode == 0' or so.

In general this is kind of broken because we create a:
 - BrowserCommandOutput object for a CompilationCommand (the first command in
'testCase.commands')
 - BrowserCommandOutput object for a BrowserTestCommand (the second command in
'testCase.commands')

(That is exactly the reason why we have the branch above!)

Normally we would like to have something like that:
 - CompilationCommandOutput object for a CompilationCommand
 - BrowserCommandOutput object for a BrowserCommand

And both CompilationCommand and BrowserCommand should be passed what we expect
(maybe we expect a warning for CompilationCommand and a runtime-error for
BrowserCommand).
CompilationCommandOutput/BrowserCommandOutput.unexpectedOutput should then make
sure that the result is what we expect.

Or we could make an even bigger change where we make 
 - a TestCase for the compilation 
 - and a different (dependent) TestCase for running the test.

This way we could mark (in the status files) if we expect the compilation to
fail, or the compilation should pass and runtime should fail or whatever.

+    }
+  }
 
   bool get hasCrashed {
     // The Java dartc runner and dart2js exits with code 253 in case
     // of unhandled exceptions.
     if (exitCode == 253) return true;
     if (io.Platform.operatingSystem == 'windows') {
       // The VM uses std::abort to terminate on asserts.
       // std::abort terminates with exit code 3 on Windows.
       if (exitCode == 3) {
         return !timedOut;
@@ skipping 350 matching lines @@
  * A RunningProcess actually runs a test, getting the command lines from
  * its [TestCase], starting the test process (and first, a compilation
  * process if the TestCase is a [BrowserTestCase]), creating a timeout
  * timer, and recording the results in a new [CommandOutput] object, which it
  * attaches to the TestCase.  The lifetime of the RunningProcess is limited
  * to the time it takes to start the process, run the process, and record
  * the result; there are no pointers to it, so it should be available to
  * be garbage collected as soon as it is done.
  */
 class RunningProcess {
-  ProcessQueue processQueue;
-  io.Process process;
   TestCase testCase;
+  Command command;
   bool timedOut = false;
   Date startTime;
   Timer timeoutTimer;
-  List<int> stdout;
-  List<int> stderr;
-  List<String> notifications;
-  bool compilationSkipped;
-  bool allowRetries;
+  List<int> stdout = <int>[];
+  List<int> stderr = <int>[];
+  bool compilationSkipped = false;
+  Completer<CommandOutput> completer;
 
-  /** Which command of [testCase.commands] is currently being executed. */
-  int currentStep;
+  RunningProcess(TestCase this.testCase, Command this.command);
 
-  RunningProcess(TestCase this.testCase,
-      [this.allowRetries = false, this.processQueue]);
+  Future<CommandOutput> start() {
+    Expect.isFalse(testCase.expectedOutcomes.contains(SKIP));
 
-  /**
-   * Called when all commands are executed.
-   */
-  void testComplete(CommandOutput lastCommandOutput) {
-    var command = lastCommandOutput.command;
+    completer = new Completer<CommandOutput>();
+    startTime = new Date.now();
+    _runCommand();
+    return completer.future;
+  }
 
+  void _runCommand() {
+    command.outputIsUpToDate.then((bool isUpToDate) {

[ricow1, 2013/01/24 09:04:28]

I would just make this function return the future, and not have the completer as
an instance variable. You can have _commandComplete as a private method in here
if you like.
Actually I don't even think you need a completer here, you can just return a
future (or a transformation in the case where you need to run the process)

[kustermann, 2013/01/29 08:43:32]

We need a completer anyway because we get the 'process.onExit' trigger
asynchronously. So let's just keep it.

+      if (isUpToDate) {
+        compilationSkipped = true;
+        _commandComplete(0);
+      } else {
+        var processOptions = _createProcessOptions();
+        Future processFuture = io.Process.start(command.executable,
+                                                command.arguments,
+                                                processOptions);
+        processFuture.then((io.Process process) {
+          void timeoutHandler(Timer unusedTimer) {
+            timedOut = true;
+            if (process != null) {
+              try {
+                process.kill();
+              } on io.ProcessException {
+                // Hopefully, this means that the process died on its own.
+              }
+            }
+          }
+          process.onExit = _commandComplete;
+          _drainStream(process.stdout, stdout);
+          _drainStream(process.stderr, stderr);
+          timeoutTimer = new Timer(1000 * testCase.timeout, timeoutHandler);
+        }).catchError((e) {
+          print("Process error:");
+          print("  Command: $command");
+          print("  Error: $e");
+          _commandComplete(-1);
+          return true;
+        });
+      }
+    });
+  }
+
+  void _commandComplete(int exitCode) {
     if (timeoutTimer != null) {
       timeoutTimer.cancel();
     }
-    if (lastCommandOutput.unexpectedOutput
-        && testCase.configuration['verbose'] != null
-        && testCase.configuration['verbose']) {
-      print(testCase.displayName);
-
-      print(decodeUtf8(lastCommandOutput.stderr));
-      if (!lastCommandOutput.command.isPixelTest) {
-        print(decodeUtf8(lastCommandOutput.stdout));
-      } else {
-        print("DRT pixel test failed! stdout is not printed because it "
-              "contains binary data!");
-      }
-      print('');
-      if (notifications.length > 0) {
-        print("Notifications:");
-        for (var line in notifications) {
-          print(notifications);
-        }
-        print('');
-      }
-    }
-    if (allowRetries && testCase.usesWebDriver
-        && lastCommandOutput.unexpectedOutput
-        && (testCase as BrowserTestCase).numRetries > 0) {
-      // Selenium tests can be flaky. Try rerunning.
-      lastCommandOutput.requestRetry = true;
-    }
-    if (lastCommandOutput.requestRetry) {
-      lastCommandOutput.requestRetry = false;
-      this.timedOut = false;
-      (testCase as BrowserTestCase).numRetries--;
-      print("Potential flake. Re-running ${testCase.displayName} "
-          "(${(testCase as BrowserTestCase).numRetries} attempt(s) remains)");
-      // When retrying we need to reset the timeout as well.
-      // Otherwise there will be no timeout handling for the retry.
-      timeoutTimer = null;
-      this.start();
-    } else {
-      testCase.completed();
-    }
+    var commandOutput = _createCommandOutput(command, exitCode);
+    completer.complete(commandOutput);
   }
 
-  /**
-   * Process exit handler called at the end of every command. It internally
-   * treats all but the last command as compilation steps. The last command is
-   * the actual test and its output is analyzed in [testComplete].
-   */
-  void commandComplete(Command command, int exitCode) {
-    process = null;
-    int totalSteps = testCase.commands.length;
-    String suffix =' (step $currentStep of $totalSteps)';
-    if (timedOut) {
-      // Non-webdriver test timed out before it could complete. Webdriver tests
-      // run their own timeouts by timing from the launch of the browser (which
-      // could be delayed).
-      testComplete(createCommandOutput(command, 0, true));
-    } else if (currentStep == totalSteps) {
-      // Done with all test commands.
-      testComplete(createCommandOutput(command, exitCode, false));
-    } else if (exitCode != 0) {
-      // One of the steps failed.
-      notifications.add('test.dart: Compilation failed$suffix, '
-                        'exit code $exitCode\n');
-      testComplete(createCommandOutput(command, exitCode, true));
-    } else {
-      createCommandOutput(command, exitCode, true);
-      // One compilation step successfully completed, move on to the
-      // next step.
-      notifications.add('test.dart: Compilation finished $suffix\n\n');
-      if (currentStep == totalSteps - 1 && testCase.usesWebDriver &&
-          !testCase.configuration['noBatch']) {
-        // Note: processQueue will always be non-null for runtime == ie9, ie10,
-        // ff, safari, chrome, opera. (It is only null for runtime == vm)
-        // This RunningProcess object is done, and hands over control to
-        // BatchRunner.startTest(), which handles reporting, etc.
-        if (timeoutTimer != null) {
-          timeoutTimer.cancel();
-        }
-        processQueue._getBatchRunner(testCase).startTest(testCase);
-      } else {
-        runCommand(testCase.commands[currentStep++], commandComplete);
-      }
-    }
-  }
-
-  /**
-   * Called for all executed commands.
-   */
-  CommandOutput createCommandOutput(Command command,
-                                    int exitCode,
-                                    bool incomplete) {
+  CommandOutput _createCommandOutput(Command command, int exitCode) {
+    var incomplete = command != testCase.commands.last;
     var commandOutput = new CommandOutput.fromCase(
         testCase,
         command,
         exitCode,
         incomplete,
         timedOut,
         stdout,
         stderr,
         new Date.now().difference(startTime),
         compilationSkipped);
-    resetLocalOutputInformation();
     return commandOutput;
   }
 
-  void resetLocalOutputInformation() {
-    stdout = new List<int>();
-    stderr = new List<int>();
-    notifications = new List<String>();
-    compilationSkipped = false;
-  }
-
-  void drainStream(io.InputStream source, List<int> destination) {
+  void _drainStream(io.InputStream source, List<int> destination) {
     void onDataHandler () {
       if (source.closed) {
         return;  // TODO(whesse): Remove when bug is fixed.
       }
       var data = source.read();
       while (data != null) {
         destination.addAll(data);
         data = source.read();
       }
     }
     source.onData = onDataHandler;
     source.onClosed = onDataHandler;
   }
 
-  void start() {
-    Expect.isFalse(testCase.expectedOutcomes.contains(SKIP));
-    resetLocalOutputInformation();
-    currentStep = 0;
-    startTime = new Date.now();
-    runCommand(testCase.commands[currentStep++], commandComplete);
-  }
-
-  void runCommand(Command command, void commandCompleteHandler(Command, int)) {
-    void processExitHandler(int returnCode) {
-      commandCompleteHandler(command, returnCode);
-    }
-
-    command.outputIsUpToDate.then((bool isUpToDate) {
-      if (isUpToDate) {
-        notifications.add("Skipped compilation because the old output is "
-                          "still up to date!");
-        compilationSkipped = true;
-        commandComplete(command, 0);
-      } else {
-        io.ProcessOptions options = new io.ProcessOptions();
-        if (command.environment != null) {
-          options.environment =
-              new Map<String, String>.from(command.environment);
-        } else {
-          options.environment =
-              new Map<String, String>.from(io.Platform.environment);
-        }
-
-        options.environment['DART_CONFIGURATION'] =
-            TestUtils.configurationDir(testCase.configuration);
-        Future processFuture = io.Process.start(command.executable,
-                                             command.arguments,
-                                             options);
-        processFuture.then((io.Process p) {
-          process = p;
-          process.onExit = processExitHandler;
-          drainStream(process.stdout, stdout);
-          drainStream(process.stderr, stderr);
-          if (timeoutTimer == null) {
-            // Create one timeout timer when starting test case, remove it at
-            // the end.
-            timeoutTimer = new Timer(1000 * testCase.timeout, timeoutHandler);
-          }
-          // If the timeout fired in between two commands, kill the just
-          // started process immediately.
-          if (timedOut) safeKill(process);
-        }).catchError((e) {
-          print("Process error:");
-          print("  Command: $command");
-          print("  Error: $e");
-          testComplete(createCommandOutput(command, -1, false));
-          return true;
-        });
-      }
-    });
-  }
-
-  void timeoutHandler(Timer unusedTimer) {
-    timedOut = true;
-    safeKill(process);
-  }
-
-  void safeKill(io.Process p) {
-    if (p != null) {
-      try {
-        p.kill();
-      } on io.ProcessException {
-        // Hopefully, this means that the process died on its own.
-      }
-    }
+  io.ProcessOptions _createProcessOptions() {
+    var baseEnvironment = command.environment != null ?
+        command.environment : io.Platform.environment;
+    io.ProcessOptions options = new io.ProcessOptions();
+    options.environment = new Map<String, String>.from(baseEnvironment);
+    options.environment['DART_CONFIGURATION'] =
+        TestUtils.configurationDir(testCase.configuration);
+    return options;
   }
 }
 
 /**
  * This class holds a value, that can be changed.  It is used when
  * closures need a shared value, that they can all change and read.
  */
 class MutableValue<T> {
   MutableValue(T this.value);
   T value;
@@ skipping 264 matching lines @@
  * have completed.
  *
  * Because multiple configurations may be run on each test suite, the
  * ProcessQueue contains a cache in which a test suite may record information
  * about its list of tests, and may retrieve that information when it is called
  * upon to enqueue its tests again.
  */
 class ProcessQueue {
   int _numProcesses = 0;
   int _maxProcesses;
+  int _numBrowserProcesses = 0;
+  int _maxBrowserProcesses;
   bool _allTestsWereEnqueued = false;
 
   /** The number of tests we allow to actually fail before we stop retrying. */
   int _MAX_FAILED_NO_RETRY = 4;
   bool _verbose;
   bool _listTests;
   Function _allDone;
   Queue<TestCase> _tests;
   ProgressIndicator _progress;
 
@@ skipping 16 matching lines @@
    * tests.)
    */
   io.Process _seleniumServer = null;
 
   /** True if we are in the process of starting the server. */
   bool _startingServer = false;
 
   /** True if we find that there is already a selenium jar running. */
   bool _seleniumAlreadyRunning = false;
 
-  ProcessQueue(int this._maxProcesses,
+  ProcessQueue(this._maxProcesses,
+               this._maxBrowserProcesses,
                String progress,
                Date startTime,
                bool printTiming,
                testSuites,
                this._allDone,
                [bool verbose = false,
                 bool listTests = false])
       : _verbose = verbose,
         _listTests = listTests,
         _tests = new Queue<TestCase>(),
@@ skipping 224 matching lines @@
         // the queue.  Avoid spin-polling by using a timeout.
         _tests.add(test);
         new Timer(100, (timer) {_tryRunTest();});  // Don't lose a process.
         return;
       }
       if (_verbose) {
         int i = 1;
         if (test is BrowserTestCase) {
           // Additional command for rerunning the steps locally after the fact.
           print('$i. ${TestUtils.dartTestExecutable.toNativePath()} '
-              '${TestUtils.dartDir().toNativePath()}/tools/testing/dart/'
-              'http_server.dart -m ${test.configuration["mode"]} '
-              '-a ${test.configuration["arch"]} '
-              '-p ${http_server.TestingServerRunner.serverList[0].port} '
-              '-c ${http_server.TestingServerRunner.serverList[1].port}');
+                '${TestUtils.dartDir().toNativePath()}/tools/testing/dart/'
+                'http_server.dart -m ${test.configuration["mode"]} '
+                '-a ${test.configuration["arch"]} '
+                '-p ${http_server.TestingServerRunner.serverList[0].port} '
+                '-c ${http_server.TestingServerRunner.serverList[1].port}');
           i++;
         }
         for (Command command in test.commands) {
           print('$i. ${command.commandLine}');
           i++;
         }
       }
+
+      var isLastCommand = ((test.commands.length-1) == test.commandOutputs.length);

[ricow1, 2013/01/24 09:04:28]

long line

[kustermann, 2013/01/29 08:43:32]

Done.

+      var isBrowserCommand = isLastCommand && (test is BrowserTestCase);
+      if (isBrowserCommand && _numBrowserProcesses == _maxBrowserProcesses) {
+        // If there is no free browser runner, put it back into the queue.

[ricow1, 2013/01/24 09:04:28]

I don't think this is an optimal solution:
Before: we would put some tests in a "queue" when selenium was not ready, now we
are basically adding new timers as fast as we can possibly compile?
How about this: We create a real queue that a batch runner scheduler will poll.
If this is a browser command, simply put it into that queue (the added benefit
of this is that we can pull out some of the functionality below that is specific
for browser/dartc).
Additionally, this will eliminate all the bookkeeping of the number of browser
processes.

[kustermann, 2013/01/29 08:43:32]

As discussed offline, we'll keep it that way.

+        _tests.add(test);
+        new Timer(100, (timer) {_tryRunTest();});  // Don't lose a process.
+
+        return;
+      }
+
       _progress.start(test);
-      TestCaseEvent oldCallback = test.completedHandler;
-      void wrapper(TestCase test_arg) {
-        _numProcesses--;
-        _progress.done(test_arg);
-        if (test_arg is BrowserTestCase) test_arg.notifyObservers();
-        _tryRunTest();
-        oldCallback(test_arg);
-      };
-      test.completedHandler = wrapper;
 
-      if ((test.configuration['compiler'] == 'dartc' &&
-           test.displayName != 'dartc/junit_tests') ||
-          (test.commands.length == 1 && test.usesWebDriver &&
-           !test.configuration['noBatch'])) {
-        // Dartc and browser test cases that do not require a precompilation
-        // step, start with the batch runner right away.
+      // Dartc and browser test commands can be run by a [BatchRunnerProcess]
+      var nextCommandIndex = test.commandOutputs.keys.length;
+      var numberOfCommands = test.commands.length;
+      var useBatchRunnerForDartc = test.configuration['compiler'] == 'dartc' &&
+                                   test.displayName != 'dartc/junit_tests';
+      var isWebdriverCommand = nextCommandIndex == (numberOfCommands - 1) &&
+                               test.usesWebDriver &&
+                               !test.configuration['noBatch'];
+      if (useBatchRunnerForDartc || isWebdriverCommand) {
+        TestCaseEvent oldCallback = test.completedHandler;
+        void wrapper(TestCase test_arg) {
+          _numProcesses--;
+          if (isBrowserCommand) {
+            _numBrowserProcesses--;
+          }
+          _progress.done(test_arg);
+          if (test_arg is BrowserTestCase) test_arg.notifyObservers();
+          oldCallback(test_arg);
+          _tryRunTest();
+        };
+        test.completedHandler = wrapper;
         _getBatchRunner(test).startTest(test);
       } else {
         // Once we've actually failed a test, technically, we wouldn't need to
         // bother retrying any subsequent tests since the bot is already red.
         // However, we continue to retry tests until we have actually failed
         // four tests (arbitrarily chosen) for more debugable output, so that
         // the developer doesn't waste his or her time trying to fix a bunch of
         // tests that appear to be broken but were actually just flakes that
         // didn't get retried because there had already been one failure.
         bool allowRetry = _MAX_FAILED_NO_RETRY > _progress.numFailedTests;
-        new RunningProcess(test, allowRetry, this).start();
+        runNextCommandWithRetries(test, allowRetry).then((TestCase testCase) {
+          _numProcesses--;
+          if (isBrowserCommand) {
+            _numBrowserProcesses--;
+          }
+          if (isTestCaseFinished(testCase)) {
+            testCase.completed();
+            _progress.done(testCase);
+            if (testCase is BrowserTestCase) testCase.notifyObservers();
+          } else {
+            _tests.add(testCase);
+          }
+          _tryRunTest();
+        });
       }
+
       _numProcesses++;
+      if (isBrowserCommand) {
+        _numBrowserProcesses++;
+      }
     }
   }
+
+  bool isTestCaseFinished(TestCase testCase) {
+    var numberOfCommandOutputs= testCase.commandOutputs.keys.length;
+    var numberOfCommands = testCase.commands.length;
+
+    var lastCommandCompleted = (numberOfCommandOutputs == numberOfCommands);
+    var unexpectedOutput = testCase.lastCommandOutput.unexpectedOutput;
+    // NOTE: If this was the last command or there was unexpected output
+    // we're done with the test.
+    // Otherwise we need to enqueue it again into the test queue.
+    if (lastCommandCompleted || unexpectedOutput) {
+      var verbose = testCase.configuration['verbose'];
+      if (unexpectedOutput && verbose != null && verbose) {
+        print(testCase.displayName);
+        print("stderr:");
+        print(decodeUtf8(commandOutput.stderr));
+        if (!command.isPixelTest) {
+          print("stdout:");
+          print(decodeUtf8(commandOutput.stdout));
+        } else {
+          print("");
+          print("DRT pixel test failed! stdout is not printed because it "
+                "contains binary data!");
+        }
+      }
+      return true;
+    } else {
+      return false;
+    }
+  }
+
+  Future runNextCommandWithRetries(TestCase testCase, bool allowRetry) {
+    var completer = new Completer();
+
+    var nextCommandIndex = testCase.commandOutputs.keys.length;
+    var numberOfCommands = testCase.commands.length;
+    Expect.isTrue(nextCommandIndex < numberOfCommands);
+    var command = testCase.commands[nextCommandIndex];
+
+    void runCommand() {
+      var runningProcess = new RunningProcess(testCase, command);
+      runningProcess.start().then((CommandOutput commandOutput) {
+        if (allowRetry && testCase.usesWebDriver
+            && commandOutput.unexpectedOutput
+            && (testCase as BrowserTestCase).numRetries > 0) {
+          // Selenium tests can be flaky. Try rerunning.
+          commandOutput.requestRetry = true;
+        }
+        if (commandOutput.requestRetry) {
+          commandOutput.requestRetry = false;
+          (testCase as BrowserTestCase).numRetries--;
+          print("Potential flake. Re-running ${testCase.displayName} "
+                "(${(testCase as BrowserTestCase).numRetries} "
+                "attempt(s) remains)");
+          runCommand();
+        } else {
+          completer.complete(testCase);
+        }
+      });
+    }
+    runCommand();
+
+    return completer.future;
+  }
 }
+