Split out long-running serialization test and add timings to output

BUG=
R=whesse@google.com

Review URL: https://codereview.chromium.org/2156033002 .

tests/compiler/dart2js/serialization/analysis_test_helper.dart

@@ -27,6 +27,7 @@ main(List<String> args) {
     } else {
       await arguments.forEachTest(serializedData, TESTS, analyze);
     }
+    printMeasurementResults();
   });
 }
 
@@ -39,27 +40,27 @@ Future analyze(
      bool verbose: false}) async {
   String testDescription = test != null ? test.name : '${entryPoint}';
   String id = index != null ? '$index: ' : '';
-  print('------------------------------------------------------------------');
-  print('analyze ${id}${testDescription}');
-  print('------------------------------------------------------------------');
-  DiagnosticCollector diagnosticCollector = new DiagnosticCollector();
-  await runCompiler(
-      entryPoint: entryPoint,
-      resolutionInputs: resolutionInputs,
-      memorySourceFiles: sourceFiles,
-      options: [Flags.analyzeOnly],
-      diagnosticHandler: diagnosticCollector);
-  if (test != null) {
-    Expect.equals(test.expectedErrorCount, diagnosticCollector.errors.length,
-        "Unexpected error count.");
-    Expect.equals(
-        test.expectedWarningCount,
-        diagnosticCollector.warnings.length,
-        "Unexpected warning count.");
-    Expect.equals(test.expectedHintCount, diagnosticCollector.hints.length,
-        "Unexpected hint count.");
-    Expect.equals(test.expectedInfoCount, diagnosticCollector.infos.length,
-        "Unexpected info count.");
-  }
+  String title = '${id}${testDescription}';
+  await measure(title, 'analyze', () async {
+    DiagnosticCollector diagnosticCollector = new DiagnosticCollector();
+    await runCompiler(
+        entryPoint: entryPoint,
+        resolutionInputs: resolutionInputs,
+        memorySourceFiles: sourceFiles,
+        options: [Flags.analyzeOnly],
+        diagnosticHandler: diagnosticCollector);
+    if (test != null) {
+      Expect.equals(test.expectedErrorCount, diagnosticCollector.errors.length,
+          "Unexpected error count.");
+      Expect.equals(
+          test.expectedWarningCount,
+          diagnosticCollector.warnings.length,
+          "Unexpected warning count.");
+      Expect.equals(test.expectedHintCount, diagnosticCollector.hints.length,
+          "Unexpected hint count.");
+      Expect.equals(test.expectedInfoCount, diagnosticCollector.infos.length,
+          "Unexpected info count.");
+    }
+  });
 }
 

tests/compiler/dart2js/serialization/compilation_test_helper.dart

@@ -28,6 +28,7 @@ main(List<String> args) {
       Uri entryPoint = Uri.parse('memory:main.dart');
       await arguments.forEachTest(serializedData, TESTS, compile);
     }
+    printMeasurementResults();
   });
 }
 
@@ -40,20 +41,20 @@ Future compile(
      bool verbose: false}) async {
   String testDescription = test != null ? test.name : '${entryPoint}';
   String id = index != null ? '$index: ' : '';
-  print('------------------------------------------------------------------');
-  print('compile ${id}${testDescription}');
-  print('------------------------------------------------------------------');
+  String title = '${id}${testDescription}';
   OutputCollector outputCollector = new OutputCollector();
-  List<String> options = [];
-  if (test.checkedMode) {
-    options.add(Flags.enableCheckedMode);
-  }
-  await runCompiler(
-      entryPoint: entryPoint,
-      memorySourceFiles: sourceFiles,
-      resolutionInputs: resolutionInputs,
-      options: options,
-      outputProvider: outputCollector);
+  await measure(title, 'compile', () async {
+    List<String> options = [];
+    if (test.checkedMode) {
+      options.add(Flags.enableCheckedMode);
+    }
+    await runCompiler(
+        entryPoint: entryPoint,
+        memorySourceFiles: sourceFiles,
+        resolutionInputs: resolutionInputs,
+        options: options,
+        outputProvider: outputCollector);
+  });
   if (verbose) {
     print(outputCollector.getOutput('', 'js'));
   }

tests/compiler/dart2js/serialization/helper.dart

@@ -115,28 +115,28 @@ typedef Future TestFunction(
      bool verbose});
 
 Future<SerializedData> serializeDartCore(
-    {Arguments arguments: const Arguments()}) async {
-  Uri uri = Uri.parse('memory:${arguments.serializedDataFileName}');
-  print('------------------------------------------------------------------');
-  print('serialize dart:core');
-  print('------------------------------------------------------------------');
-  SerializedData serializedData;
-  if (arguments.loadSerializedData) {
-    File file = new File(arguments.serializedDataFileName);
-    if (file.existsSync()) {
-      print('Loading data from $file');
-      serializedData = new SerializedData(uri, file.readAsStringSync());
+    {Arguments arguments: const Arguments()}) {
+  return measure('dart:core', 'serialize', () async {
+    Uri uri = Uri.parse('memory:${arguments.serializedDataFileName}');
+    SerializedData serializedData;
+    if (arguments.loadSerializedData) {
+      File file = new File(arguments.serializedDataFileName);
+      if (file.existsSync()) {
+        print('Loading data from $file');
+        serializedData = new SerializedData(uri, file.readAsStringSync());
+      }
+    } else {
+      SerializationResult result =
+          await serialize(Uris.dart_core, dataUri: uri);
+      serializedData = result.serializedData;
     }
-  } else {
-    SerializationResult result = await serialize(Uris.dart_core, dataUri: uri);
-    serializedData = result.serializedData;
-  }
-  if (arguments.saveSerializedData) {
-    File file = new File(arguments.serializedDataFileName);
-    print('Saving data to $file');
-    file.writeAsStringSync(serializedData.data);
-  }
-  return serializedData;
+    if (arguments.saveSerializedData) {
+      File file = new File(arguments.serializedDataFileName);
+      print('Saving data to $file');
+      file.writeAsStringSync(serializedData.data);
+    }
+    return serializedData;
+  });
 }
 
 class SerializationResult {
@@ -236,3 +236,59 @@ Future<List<SerializedData>> preserializeData(
       outputCollector.getOutput('', 'data'));
   return <SerializedData>[serializedData, additionalSerializedData];
 }
+
+class MeasurementResult {
+  final String title;
+  final String taskTitle;
+  final int elapsedMilliseconds;
+
+  MeasurementResult(this.title, this.taskTitle, this.elapsedMilliseconds);
+}
+
+final List<MeasurementResult> measurementResults = <MeasurementResult>[];
+
+/// Print all store [measurementResults] grouped by title and sorted by
+/// decreasing execution time.
+void printMeasurementResults() {
+  Map<String, int> totals = <String, int>{};
+
+  for (MeasurementResult result in measurementResults) {
+    totals.putIfAbsent(result.title, () => 0);
+    totals[result.title] += result.elapsedMilliseconds;
+  }
+
+  List<String> sorted = totals.keys.toList();
+  sorted.sort((a, b) => -totals[a].compareTo(totals[b]));
+
+  int paddingLength = '${totals[sorted.first]}'.length;
+
+  String pad(int value) {
+    String text = '$value';
+    return '${' ' * (paddingLength - text.length)}$text';
+  }
+
+  print('================================================================');
+  print('Summary:');
+  for (String task in sorted) {
+    int time = totals[task];
+    print('${pad(time)}ms $task');
+  }
+
+  measurementResults.clear();
+}
+
+/// Measure execution of [task], print the result and store it in
+/// [measurementResults] for a summary.
+Future measure(String title, String taskTitle, Future task()) async {
+  Stopwatch stopwatch = new Stopwatch()..start();
+  print('================================================================');
+  print('$taskTitle: $title');
+  print('----------------------------------------------------------------');
+  var result = await task();
+  stopwatch.stop();
+  int elapsedMilliseconds = stopwatch.elapsedMilliseconds;
+  print('$taskTitle: $title: ${elapsedMilliseconds}ms');
+  measurementResults.add(
+      new MeasurementResult(title, taskTitle, elapsedMilliseconds));
+  return result;
+}

tests/compiler/dart2js/serialization/model0_test.dart

@@ -0,0 +1,12 @@
+// Copyright (c) 2016, 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.
+
+library dart2js.serialization.model0_test;
+
+import 'model_test_helper.dart' as test;
+import 'test_data.dart';
+
+main() {
+  test.main(['0', '0']);
+}

tests/compiler/dart2js/serialization/model1_test.dart

@@ -8,5 +8,5 @@ import 'model_test_helper.dart' as test;
 import 'test_data.dart';
 
 main() {
-  test.main(['0', '${TESTS.length ~/ 2}']);
+  test.main(['1', '${TESTS.length ~/ 2}']);
 }

tests/compiler/dart2js/serialization/model_test_helper.dart

@@ -31,14 +31,14 @@ main(List<String> args) {
         await serializeDartCore(arguments: arguments);
     if (arguments.filename != null) {
       Uri entryPoint = Uri.base.resolve(nativeToUriPath(arguments.filename));
-      print('----------------------------------------------------------------');
-      print('serialize ${entryPoint}');
-      print('----------------------------------------------------------------');
-      SerializationResult result = await serialize(
-          entryPoint,
-          memorySourceFiles: serializedData.toMemorySourceFiles(),
-          resolutionInputs: serializedData.toUris(),
-          dataUri: Uri.parse('memory:test.data'));
+      SerializationResult result = await measure(
+          '${entryPoint}', 'serialize', () {
+        return serialize(
+            entryPoint,
+            memorySourceFiles: serializedData.toMemorySourceFiles(),
+            resolutionInputs: serializedData.toUris(),
+            dataUri: Uri.parse('memory:test.data'));
+      });
       await checkModels(entryPoint,
           sourceFiles: serializedData.toMemorySourceFiles(
               result.serializedData.toMemorySourceFiles()),
@@ -48,6 +48,7 @@ main(List<String> args) {
       Uri entryPoint = Uri.parse('memory:main.dart');
       await arguments.forEachTest(serializedData, TESTS, checkModels);
     }
+    printMeasurementResults();
   });
 }
 
@@ -60,96 +61,101 @@ Future checkModels(
      bool verbose: false}) async {
   String testDescription = test != null ? test.name : '${entryPoint}';
   String id = index != null ? '$index: ' : '';
-  print('------------------------------------------------------------------');
-  print('compile normal ${id}${testDescription}');
-  print('------------------------------------------------------------------');
-  Compiler compilerNormal = compilerFor(
-      memorySourceFiles: sourceFiles,
-      options: [Flags.analyzeOnly]);
-  compilerNormal.resolution.retainCachesForTesting = true;
-  await compilerNormal.run(entryPoint);
-  compilerNormal.phase = Compiler.PHASE_DONE_RESOLVING;
-  compilerNormal.world.populate();
-  compilerNormal.backend.onResolutionComplete();
-  compilerNormal.deferredLoadTask.onResolutionComplete(
-      compilerNormal.mainFunction);
+  String title = '${id}${testDescription}';
+  Compiler compilerNormal = await measure(
+      title, 'compile normal', () async {
+    Compiler compilerNormal = compilerFor(
+        memorySourceFiles: sourceFiles,
+        options: [Flags.analyzeOnly]);
+    compilerNormal.resolution.retainCachesForTesting = true;
+    await compilerNormal.run(entryPoint);
+    compilerNormal.phase = Compiler.PHASE_DONE_RESOLVING;
+    compilerNormal.world.populate();
+    compilerNormal.backend.onResolutionComplete();
+    compilerNormal.deferredLoadTask.onResolutionComplete(
+        compilerNormal.mainFunction);
+    return compilerNormal;
+  });
 
-  print('------------------------------------------------------------------');
-  print('compile deserialized ${id}${testDescription}');
-  print('------------------------------------------------------------------');
-  Compiler compilerDeserialized = compilerFor(
-      memorySourceFiles: sourceFiles,
-      resolutionInputs: resolutionInputs,
-      options: [Flags.analyzeOnly]);
-  compilerDeserialized.resolution.retainCachesForTesting = true;
-  await compilerDeserialized.run(entryPoint);
-  compilerDeserialized.phase = Compiler.PHASE_DONE_RESOLVING;
-  compilerDeserialized.world.populate();
-  compilerDeserialized.backend.onResolutionComplete();
-  compilerDeserialized.deferredLoadTask.onResolutionComplete(
-      compilerDeserialized.mainFunction);
+  Compiler compilerDeserialized = await measure(
+      title, 'compile deserialized', () async {
+    Compiler compilerDeserialized = compilerFor(
+        memorySourceFiles: sourceFiles,
+        resolutionInputs: resolutionInputs,
+        options: [Flags.analyzeOnly]);
+    compilerDeserialized.resolution.retainCachesForTesting = true;
+    await compilerDeserialized.run(entryPoint);
+    compilerDeserialized.phase = Compiler.PHASE_DONE_RESOLVING;
+    compilerDeserialized.world.populate();
+    compilerDeserialized.backend.onResolutionComplete();
+    compilerDeserialized.deferredLoadTask.onResolutionComplete(
+        compilerDeserialized.mainFunction);
+    return compilerDeserialized;
+  });
 
-  checkAllImpacts(
-      compilerNormal, compilerDeserialized,
-      verbose: verbose);
+  return measure(title, 'check models', () async {
+    checkAllImpacts(
+        compilerNormal, compilerDeserialized,
+        verbose: verbose);
 
-  checkSets(
-      compilerNormal.resolverWorld.directlyInstantiatedClasses,
-      compilerDeserialized.resolverWorld.directlyInstantiatedClasses,
-      "Directly instantiated classes mismatch",
-      areElementsEquivalent,
-      verbose: verbose);
+    checkSets(
+        compilerNormal.resolverWorld.directlyInstantiatedClasses,
+        compilerDeserialized.resolverWorld.directlyInstantiatedClasses,
+        "Directly instantiated classes mismatch",
+        areElementsEquivalent,
+        verbose: verbose);
 
-  checkSets(
-      compilerNormal.resolverWorld.instantiatedTypes,
-      compilerDeserialized.resolverWorld.instantiatedTypes,
-      "Instantiated types mismatch",
-      areTypesEquivalent,
-      verbose: verbose);
+    checkSets(
+        compilerNormal.resolverWorld.instantiatedTypes,
+        compilerDeserialized.resolverWorld.instantiatedTypes,
+        "Instantiated types mismatch",
+        areTypesEquivalent,
+        verbose: verbose);
 
-  checkSets(
-      compilerNormal.resolverWorld.isChecks,
-      compilerDeserialized.resolverWorld.isChecks,
-      "Is-check mismatch",
-      areTypesEquivalent,
-      verbose: verbose);
+    checkSets(
+        compilerNormal.resolverWorld.isChecks,
+        compilerDeserialized.resolverWorld.isChecks,
+        "Is-check mismatch",
+        areTypesEquivalent,
+        verbose: verbose);
 
-  checkSets(
-      compilerNormal.enqueuer.resolution.processedElements,
-      compilerDeserialized.enqueuer.resolution.processedElements,
-      "Processed element mismatch",
-      areElementsEquivalent,
-      onSameElement: (a, b) {
-        checkElements(
-            compilerNormal, compilerDeserialized, a, b, verbose: verbose);
-      },
-      verbose: verbose);
+    checkSets(
+        compilerNormal.enqueuer.resolution.processedElements,
+        compilerDeserialized.enqueuer.resolution.processedElements,
+        "Processed element mismatch",
+        areElementsEquivalent,
+        onSameElement: (a, b) {
+          checkElements(
+              compilerNormal, compilerDeserialized, a, b, verbose: verbose);
+        },
+        verbose: verbose);
 
-  checkClassHierarchyNodes(
-      compilerNormal,
-      compilerDeserialized,
-      compilerNormal.world.getClassHierarchyNode(
-          compilerNormal.coreClasses.objectClass),
-      compilerDeserialized.world.getClassHierarchyNode(
-          compilerDeserialized.coreClasses.objectClass),
-      verbose: verbose);
+    checkClassHierarchyNodes(
+        compilerNormal,
+        compilerDeserialized,
+        compilerNormal.world.getClassHierarchyNode(
+            compilerNormal.coreClasses.objectClass),
+        compilerDeserialized.world.getClassHierarchyNode(
+            compilerDeserialized.coreClasses.objectClass),
+        verbose: verbose);
 
-  Expect.equals(compilerNormal.enabledInvokeOn,
-      compilerDeserialized.enabledInvokeOn,
-      "Compiler.enabledInvokeOn mismatch");
-  Expect.equals(compilerNormal.enabledFunctionApply,
-      compilerDeserialized.enabledFunctionApply,
-      "Compiler.enabledFunctionApply mismatch");
-  Expect.equals(compilerNormal.enabledRuntimeType,
-      compilerDeserialized.enabledRuntimeType,
-      "Compiler.enabledRuntimeType mismatch");
-  Expect.equals(compilerNormal.hasIsolateSupport,
-      compilerDeserialized.hasIsolateSupport,
-      "Compiler.hasIsolateSupport mismatch");
-  Expect.equals(
-      compilerNormal.deferredLoadTask.isProgramSplit,
-      compilerDeserialized.deferredLoadTask.isProgramSplit,
-      "isProgramSplit mismatch");
+    Expect.equals(compilerNormal.enabledInvokeOn,
+        compilerDeserialized.enabledInvokeOn,
+        "Compiler.enabledInvokeOn mismatch");
+    Expect.equals(compilerNormal.enabledFunctionApply,
+        compilerDeserialized.enabledFunctionApply,
+        "Compiler.enabledFunctionApply mismatch");
+    Expect.equals(compilerNormal.enabledRuntimeType,
+        compilerDeserialized.enabledRuntimeType,
+        "Compiler.enabledRuntimeType mismatch");
+    Expect.equals(compilerNormal.hasIsolateSupport,
+        compilerDeserialized.hasIsolateSupport,
+        "Compiler.hasIsolateSupport mismatch");
+    Expect.equals(
+        compilerNormal.deferredLoadTask.isProgramSplit,
+        compilerDeserialized.deferredLoadTask.isProgramSplit,
+        "isProgramSplit mismatch");
+  });
 }
 
 void checkElements(