Truncate excessively long output from tests in test.dart.

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 652 matching lines @@
   }
 
   Command getModifyPubspecCommand(String pubspecYamlFile, Map depsOverrides,
                                   {String destinationFile: null}) {
     if (destinationFile == null) destinationFile = pubspecYamlFile;
     return _getUniqueCommand(new ModifyPubspecYamlCommand._(
         pubspecYamlFile, destinationFile, depsOverrides));
   }
 
   Command _getUniqueCommand(Command command) {
-    // All Command classes have hashCode/operator==, so we check if this command
-    // has already been build, if so we return the cached one, otherwise we
+    // All Command classes implement hashCode and operator==.
+    // We check if this command has already been built.
+    //  If so, we return the cached one. Otherwise we
     // store the one given as [command] argument.
     var cachedCommand = _cachedCommands[command];
     if (cachedCommand != null) {
       return cachedCommand;
     }
     _cachedCommands[command] = command;
     return command;
   }
 }
 
@@ skipping 982 matching lines @@
         command, exitCode, timedOut, stdout, stderr, time);
   }
 
   return new CommandOutputImpl(
       command, exitCode, timedOut, stdout, stderr,
       time, compilationSkipped, pid);
 }
 
 
 /**
+ * An OutputLog records the output from a test, but truncates it if
+ * it is longer than MAX_HEAD characters, and just keeps the head and
+ * the last TAIL_LENGTH characters of the output.
+ */
+class OutputLog {
+  static const int MAX_HEAD = 100 * 1024;
+  static const int TAIL_LENGTH = 10 * 1024;
+  List<int> head = <int>[];
+  List<int> tail;
+  List<int> complete;
+  bool dataDropped = false;
+
+  OutputLog();
+
+  void add(List<int> data) {
+    if (complete != null) {
+      throw new StateError("Cannot add to OutputLog after calling toList");
+    }
+    if (tail == null) {
+      head.addAll(data);
+      if (head.length > MAX_HEAD) {
+        tail = head.sublist(MAX_HEAD);
+        head.length = MAX_HEAD;

[Ivan Posva, 2014/04/10 00:10:44]

This is making matters actually worse, ending up using more memory. Now you
have:
- A tail list containing everything after the cutoff, which is the result of the
sublist call.
- A head list of the original capacity, but the length having been reset with
the call to length. Also you did have to go through the whole overhang and set
all elements to null.

[Bill Hesse, 2014/04/11 07:39:48]

These variables are only live while the test is running.  As soon as the test
completes, both head and tail are dropped, and can be GCd, because toList has
been called.

Tail is also truncated on an ongoing basis.  I don't see any major improvements
that could be made - using head = head.sublist would not be better than
head.length, unless head was much longer than MAX_HEAD.


According to tests, this does reduce memory use by about 25%, or 40 MB.  It may
not save 25% when running 10 configurations though.

+      }
+    } else {
+      tail.addAll(data);
+    }
+    if (tail != null && tail.length > 2 * TAIL_LENGTH) {
+      tail = _truncatedTail();
+      dataDropped = true;
+    }
+  }
+
+  List<int> _truncatedTail() =>
+    tail.length > TAIL_LENGTH ?
+        tail.sublist(tail.length - TAIL_LENGTH) :
+        tail;
+
+  List<int> toList() {
+    if (complete == null) {
+      complete = head;
+      if (dataDropped) {
+        complete.addAll("""
+
+*****************************************************************************
+
+Data removed due to excessive length
+
+*****************************************************************************
+
+""".codeUnits);
+        complete.addAll(_truncatedTail());
+      } else if (tail != null) {
+        complete.addAll(tail);
+      }
+      head = null;
+      tail = null;
+    }
+    return complete;
+  }
+}
+
+/**
  * 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 {
   ProcessCommand command;
   int timeout;
   bool timedOut = false;
   DateTime startTime;
   Timer timeoutTimer;
   int pid;
-  List<int> stdout = <int>[];
-  List<int> stderr = <int>[];
+  OutputLog stdout = new OutputLog();
+  OutputLog stderr = new OutputLog();
   bool compilationSkipped = false;
   Completer<CommandOutput> completer;
 
   RunningProcess(this.command, this.timeout);
 
   Future<CommandOutput> run() {
     completer = new Completer<CommandOutput>();
     startTime = new DateTime.now();
     _runCommand();
     return completer.future;
@@ skipping 102 matching lines @@
     }
     var commandOutput = _createCommandOutput(command, exitCode);
     completer.complete(commandOutput);
   }
 
   CommandOutput _createCommandOutput(ProcessCommand command, int exitCode) {
     var commandOutput = createCommandOutput(
         command,
         exitCode,
         timedOut,
-        stdout,
-        stderr,
+        stdout.toList(),
+        stderr.toList(),
         new DateTime.now().difference(startTime),
         compilationSkipped,
         pid);
     return commandOutput;
   }
 
   StreamSubscription _drainStream(Stream<List<int>> source,
-                                  List<int> destination) {
-    return source.listen(destination.addAll);
+                                  OutputLog destination) {
+    return source.listen(destination.add);
   }
 
   Map<String, String> _createProcessEnvironment() {
     var environment = new Map.from(io.Platform.environment);
 
     if (command.environmentOverrides != null) {
       for (var key in command.environmentOverrides.keys) {
         environment[key] = command.environmentOverrides[key];
       }
     }
@@ skipping 30 matching lines @@
 
   io.Process _process;
   Map _processEnvironmentOverrides;
   Completer _stdoutCompleter;
   Completer _stderrCompleter;
   StreamSubscription<String> _stdoutSubscription;
   StreamSubscription<String> _stderrSubscription;
   Function _processExitHandler;
 
   bool _currentlyRunning = false;
-  List<int> _testStdout;
-  List<int> _testStderr;
+  OutputLog _testStdout;
+  OutputLog _testStderr;
   String _status;
   DateTime _startTime;
   Timer _timer;
 
   BatchRunnerProcess();
 
   Future<CommandOutput> runCommand(String runnerType, ProcessCommand command,
                                    int timeout, List<String> arguments) {
     assert(_completer == null);
     assert(!_currentlyRunning);
@@ skipping 35 matching lines @@
       if (killTimer != null) killTimer.cancel();
       terminateCompleter.complete(true);
     };
     _process.kill();
 
     return terminateCompleter.future;
   }
 
   void doStartTest(Command command, int timeout) {
     _startTime = new DateTime.now();
-    _testStdout = [];
-    _testStderr = [];
+    _testStdout = new OutputLog();
+    _testStderr = new OutputLog();
     _status = null;
     _stdoutCompleter = new Completer();
     _stderrCompleter = new Completer();
     _timer = new Timer(new Duration(seconds: timeout),
                        _timeoutHandler);
 
     var line = _createArgumentsLine(_arguments, timeout);
     _process.stdin.write(line);
     _stdoutSubscription.resume();
     _stderrSubscription.resume();
     Future.wait([_stdoutCompleter.future,
                  _stderrCompleter.future]).then((_) => _reportResult());
   }
 
   String _createArgumentsLine(List<String> arguments, int timeout) {
     return arguments.join(' ') + '\n';
   }
 
   void _reportResult() {
     if (!_currentlyRunning) return;
     // _status == '>>> TEST {PASS, FAIL, OK, CRASH, FAIL, TIMEOUT}'
 
     var outcome = _status.split(" ")[2];
     var exitCode = 0;
     if (outcome == "CRASH") exitCode = CRASHING_BROWSER_EXITCODE;
     if (outcome == "FAIL" || outcome == "TIMEOUT") exitCode = 1;
     var output = createCommandOutput(_command,
                         exitCode,
                         (outcome == "TIMEOUT"),
-                        _testStdout,
-                        _testStderr,
+                        _testStdout.toList(),
+                        _testStderr.toList(),
                         new DateTime.now().difference(_startTime),
                         false);
     assert(_completer != null);
     _completer.complete(output);
     _completer = null;
     _currentlyRunning = false;
   }
 
   ExitCodeEvent makeExitHandler(String status) {
     void handler(int exitCode) {
@@ skipping 35 matching lines @@
               .transform(UTF8.decoder)
               .transform(new LineSplitter());
       _stdoutSubscription = _stdoutStream.listen((String line) {
         if (line.startsWith('>>> TEST')) {
           _status = line;
         } else if (line.startsWith('>>> BATCH')) {
           // ignore
         } else if (line.startsWith('>>> ')) {
           throw new Exception("Unexpected command from batch runner: '$line'.");
         } else {
-          _testStdout.addAll(encodeUtf8(line));
-          _testStdout.addAll("\n".codeUnits);
+          _testStdout.add(encodeUtf8(line));
+          _testStdout.add("\n".codeUnits);
         }
         if (_status != null) {
           _stdoutSubscription.pause();
           _timer.cancel();
           _stdoutCompleter.complete(null);
         }
       });
       _stdoutSubscription.pause();
 
       var _stderrStream =
           _process.stderr
               .transform(UTF8.decoder)
               .transform(new LineSplitter());
       _stderrSubscription = _stderrStream.listen((String line) {
         if (line.startsWith('>>> EOF STDERR')) {
           _stderrSubscription.pause();
           _stderrCompleter.complete(null);
         } else {
-          _testStderr.addAll(encodeUtf8(line));
-          _testStderr.addAll("\n".codeUnits);
+          _testStderr.add(encodeUtf8(line));
+          _testStderr.add("\n".codeUnits);
         }
       });
       _stderrSubscription.pause();
 
       _processExitHandler = makeExitHandler(">>> TEST CRASH");
       _process.exitCode.then((exitCode) {
         _processExitHandler(exitCode);
       });
 
       _process.stdin.done.catchError((err) {
@@ skipping 815 matching lines @@
     }
   }
 
   void eventAllTestsDone() {
     for (var listener in _eventListener) {
       listener.allDone();
     }
     _allDone();
   }
 }