Use Zone to correctly measure async operations.

pkg/compiler/lib/src/compiler.dart

Index: pkg/compiler/lib/src/compiler.dart
diff --git a/pkg/compiler/lib/src/compiler.dart b/pkg/compiler/lib/src/compiler.dart
index bc7dfe0e3982787e6b721aac2a3806c6eb67e300..ed9283dc17a55d98fae79de22f03664efdc1e04e 100644
--- a/pkg/compiler/lib/src/compiler.dart
+++ b/pkg/compiler/lib/src/compiler.dart
@@ -16,7 +16,7 @@ import 'common/names.dart' show Identifiers, Uris;
 import 'common/registry.dart' show EagerRegistry, Registry;
 import 'common/resolution.dart'
     show ParsingContext, Resolution, ResolutionWorkItem, ResolutionImpact;
-import 'common/tasks.dart' show CompilerTask, GenericTask;
+import 'common/tasks.dart' show CompilerTask, GenericTask, Measurer;
 import 'common/work.dart' show ItemCompilationContext, WorkItem;
 import 'common.dart';
 import 'compile_time_constants.dart';
@@ -80,7 +80,12 @@ import 'util/util.dart' show Link, Setlet;
 import 'world.dart' show World;
 
 abstract class Compiler implements LibraryLoaderListener {
-  final Stopwatch totalCompileTime = new Stopwatch();
+  /// Helper instance for measurements in [CompilerTask].
+  ///
+  /// Note: MUST be first field to ensure [Measurer.wallclock] is started
+  /// before other computations.
+  final Measurer measurer = new Measurer();
+
   final IdGenerator idGenerator = new IdGenerator();
   World world;
   Types types;
@@ -135,7 +140,6 @@ abstract class Compiler implements LibraryLoaderListener {
 
   Tracer tracer;
 
-  CompilerTask measuredTask;
   LibraryElement coreLibrary;
   LibraryElement asyncLibrary;
 
@@ -234,6 +238,8 @@ abstract class Compiler implements LibraryLoaderListener {
 
   GenericTask reuseLibraryTask;
 
+  GenericTask selfTask;
+
   /// The constant environment for the frontend interpretation of compile-time
   /// constants.
   ConstantEnvironment constants;
@@ -349,6 +355,7 @@ abstract class Compiler implements LibraryLoaderListener {
       enqueuer = new EnqueueTask(this),
       dumpInfoTask = new DumpInfoTask(this),
       reuseLibraryTask = new GenericTask('Reuse library', this),
+      selfTask = new GenericTask('self', this),
     ];
 
     _parsingContext =
@@ -388,18 +395,18 @@ abstract class Compiler implements LibraryLoaderListener {
   //
   // The resulting future will complete with true if the compilation
   // succeeded.
-  Future<bool> run(Uri uri) {
-    totalCompileTime.start();
+  Future<bool> run(Uri uri) => selfTask.measureSubtask("Compiler.run", () {
+    measurer.startWallClock();

[Johnni Winther, 2016/04/25 09:23:02]

Why do call [startWallClock] here? Isn't is already started?

What about the time used in the subclass (apiimpl) before its super-call?

[ahe, 2016/04/26 11:35:00]

For normal dart2js runs from the command line, it is started already. However,
when calling run multiple times, it isn't.
This isn't ideal, but I'm not sure what would be a better alternative.

 
     return new Future.sync(() => runInternal(uri))
         .catchError((error) => _reporter.onError(uri, error))
         .whenComplete(() {
       tracer.close();
-      totalCompileTime.stop();
+      measurer.stopWallClock();
     }).then((_) {
       return !compilationFailed;
     });
-  }
+  });
 
   /// This method is called immediately after the [LibraryElement] [library] has
   /// been created.
@@ -786,7 +793,9 @@ abstract class Compiler implements LibraryLoaderListener {
   }
 
   /// Performs the compilation when all libraries have been loaded.
-  void compileLoadedLibraries() {
+  void compileLoadedLibraries()
+      => selfTask.measureSubtask("Compiler.compileLoadedLibraries", () {
+
     computeMain();
 
     mirrorUsageAnalyzerTask.analyzeUsage(mainApp);
@@ -889,7 +898,7 @@ abstract class Compiler implements LibraryLoaderListener {
     backend.sourceInformationStrategy.onComplete();
 
     checkQueues();
-  }
+  });
 
   void fullyEnqueueLibrary(LibraryElement library, Enqueuer world) {
     void enqueueAll(Element element) {
@@ -925,15 +934,20 @@ abstract class Compiler implements LibraryLoaderListener {
   /**
    * Empty the [world] queue.
    */
-  void emptyQueue(Enqueuer world) {
+  void emptyQueue(Enqueuer world)
+      => selfTask.measureSubtask("Compiler.emptyQueue", () {
     world.forEach((WorkItem work) {
-      reporter.withCurrentElement(work.element, () {
-        world.applyImpact(work.element, work.run(this, world));
-      });
+      reporter.withCurrentElement(
+          work.element, () => selfTask.measureSubtask("world.applyImpact", () {
+        world.applyImpact(
+            work.element,
+            selfTask.measureSubtask("work.run", () => work.run(this, world)));
+      }));
     });
-  }
+  });
 
-  void processQueue(Enqueuer world, Element main) {
+  void processQueue(Enqueuer world, Element main)
+      => selfTask.measureSubtask("Compiler.processQueue", () {
     world.nativeEnqueuer.processNativeClasses(libraryLoader.libraries);
     if (main != null && !main.isMalformed) {
       FunctionElement mainMethod = main;
@@ -961,7 +975,7 @@ abstract class Compiler implements LibraryLoaderListener {
     impactStrategy.onImpactUsed(world.impactUse);
     backend.onQueueClosed();
     assert(compilationFailed || world.checkNoEnqueuedInvokedInstanceMethods());
-  }
+  });
 
   /**
    * Perform various checks of the queues. This includes checking that
@@ -1002,7 +1016,8 @@ abstract class Compiler implements LibraryLoaderListener {
     }
   }
 
-  WorldImpact analyzeElement(Element element) {
+  WorldImpact analyzeElement(Element element)
+      => selfTask.measureSubtask("Compiler.analyzeElement", () {
     assert(invariant(
         element,
         element.impliesType ||
@@ -1016,9 +1031,11 @@ abstract class Compiler implements LibraryLoaderListener {
         message: 'Element $element is not analyzable.'));
     assert(invariant(element, element.isDeclaration));
     return resolution.computeWorldImpact(element);
-  }
+  });
 
-  WorldImpact analyze(ResolutionWorkItem work, ResolutionEnqueuer world) {
+  WorldImpact analyze(ResolutionWorkItem work,
+                      ResolutionEnqueuer world)
+      => selfTask.measureSubtask("Compiler.analyze", () {
     assert(invariant(work.element, identical(world, enqueuer.resolution)));
     assert(invariant(work.element, !work.isAnalyzed,
         message: 'Element ${work.element} has already been analyzed'));
@@ -1039,7 +1056,7 @@ abstract class Compiler implements LibraryLoaderListener {
     backend.onElementResolved(element);
     world.registerProcessedElement(element);
     return worldImpact;
-  }
+  });
 
   WorldImpact codegen(CodegenWorkItem work, CodegenEnqueuer world) {
     assert(invariant(work.element, identical(world, enqueuer.codegen)));