Use Zone to correctly measure async operations.

pkg/compiler/lib/src/apiimpl.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.
 
 library leg_apiimpl;
 
 import 'dart:async';
 import 'dart:convert';
 
 import 'package:package_config/packages.dart';
 import 'package:package_config/packages_file.dart' as pkgs;
 import 'package:package_config/src/packages_impl.dart'
     show MapPackages, NonFilePackagesDirectoryPackages;
 import 'package:package_config/src/util.dart' show checkValidPackageUri;
 
 import '../compiler_new.dart' as api;
-import 'common/tasks.dart' show GenericTask;
+import 'common/tasks.dart' show GenericTask, Measurer;
 import 'common.dart';
 import 'compiler.dart';
 import 'diagnostics/messages.dart' show Message;
 import 'elements/elements.dart' as elements;
 import 'environment.dart';
 import 'io/source_file.dart';
 import 'options.dart' show CompilerOptions;
 import 'platform_configuration.dart' as platform_configuration;
 import 'resolved_uri_translator.dart';
 import 'script.dart';
@@ skipping 124 matching lines @@
     }
     return packages.resolve(uri, notFound: (Uri notFound) {
       reporter.reportErrorMessage(
           node, MessageKind.LIBRARY_NOT_FOUND, {'resolvedUri': uri});
       return null;
     });
   }
 
   Future<elements.LibraryElement> analyzeUri(Uri uri,
       {bool skipLibraryWithPartOfTag: true}) {
-    List<Future> setupFutures = new List<Future>();
+    Future setupFuture = new Future.value();
     if (resolvedUriTranslator.isNotSet) {
-      setupFutures.add(setupSdk());
+      setupFuture = setupFuture.then((_) => setupSdk());
     }
     if (packages == null) {
-      setupFutures.add(setupPackages(uri));
+      setupFuture = setupFuture.then((_) => setupPackages(uri));
     }
-    return Future.wait(setupFutures).then((_) {
+    return setupFuture.then((_) {
       return super
           .analyzeUri(uri, skipLibraryWithPartOfTag: skipLibraryWithPartOfTag);
     });
   }
 
   Future setupPackages(Uri uri) {
     if (options.packageRoot != null) {
       // Use "non-file" packages because the file version requires a [Directory]
       // and we can't depend on 'dart:io' classes.
       packages = new NonFilePackagesDirectoryPackages(options.packageRoot);
@@ skipping 37 matching lines @@
             new ResolvedUriTranslator(mapping, reporter);
       });
     } else {
       // The incremental compiler sets up the sdk before run.
       // Therefore this will be called a second time.
       return new Future.value(null);
     }
   }
 
   Future<bool> run(Uri uri) {
-    log('Using platform configuration at ${options.platformConfigUri}');
+    Duration setupDuration = measurer.wallClock.elapsed;
+    return selfTask.measureSubtask("CompilerImpl.run", () {
+      log('Using platform configuration at ${options.platformConfigUri}');
 
-    return Future.wait([setupSdk(), setupPackages(uri)]).then((_) {
-      assert(resolvedUriTranslator.isSet);
-      assert(packages != null);
+      return setupSdk().then((_) => setupPackages(uri)).then((_) {
+        assert(resolvedUriTranslator.isSet);
+        assert(packages != null);
 
-      return super.run(uri).then((bool success) {
-        int cumulated = 0;
+        return super.run(uri);
+      }).then((bool success) {
+        StringBuffer timings = new StringBuffer();

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

Can we avoid the computation of [timings] when we're not verbose?

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

Done.

+        timings.writeln("Timings:");
+        Duration totalDuration = measurer.wallClock.elapsed;
+        Duration asyncDuration = measurer.asyncWallClock.elapsed;
+        Duration cumulatedDuration = Duration.ZERO;
         for (final task in tasks) {
-          int elapsed = task.timing;
-          if (elapsed != 0) {
-            cumulated += elapsed;
-            log('${task.name} took ${elapsed}msec');
+          String running = task.isRunning ? "*" : "";
+          Duration duration = task.duration;
+          if (duration != Duration.ZERO) {
+            cumulatedDuration += duration;
+            timings.writeln(
+                '    $running${task.name} took'
+                ' ${duration.inMilliseconds}msec');
             for (String subtask in task.subtasks) {
               int subtime = task.getSubtaskTime(subtask);
-              log('${task.name} > $subtask took ${subtime}msec');
+              String running = task.getSubtaskIsRunning(subtask) ? "*" : "";
+              timings.writeln(
+                  '    $running${task.name} > $subtask took ${subtime}msec');
             }
           }
         }
-        int total = totalCompileTime.elapsedMilliseconds;
-        log('Total compile-time ${total}msec;'
-            ' unaccounted ${total - cumulated}msec');
+        Duration unaccountedDuration =
+            totalDuration - cumulatedDuration - setupDuration - asyncDuration;
+        double percent = unaccountedDuration.inMilliseconds * 100
+            / totalDuration.inMilliseconds;
+        timings.write(
+            '    Total compile-time ${totalDuration.inMilliseconds}msec;'
+            ' setup ${setupDuration.inMilliseconds}msec;'
+            ' async ${asyncDuration.inMilliseconds}msec;'
+            ' unaccounted ${unaccountedDuration.inMilliseconds}msec'
+            ' (${percent.toStringAsFixed(2)}%)');
+        log("$timings");
         return success;
       });
     });
   }
 
   void reportDiagnostic(DiagnosticMessage message,
       List<DiagnosticMessage> infos, api.Diagnostic kind) {
     _reportDiagnosticMessage(message, kind);
     for (DiagnosticMessage info in infos) {
       _reportDiagnosticMessage(info, api.Diagnostic.INFO);
@@ skipping 18 matching lines @@
       mockableLibraryUsed && options.allowMockCompilation;
 
   void callUserHandler(Message message, Uri uri, int begin, int end,
       String text, api.Diagnostic kind) {
     userHandlerTask.measure(() {
       handler.report(message, uri, begin, end, text, kind);
     });
   }
 
   Future callUserProvider(Uri uri) {
-    return userProviderTask.measure(() => provider.readFromUri(uri));
+    return userProviderTask.measureIo(() => provider.readFromUri(uri));
   }
 
   Future<Packages> callUserPackagesDiscovery(Uri uri) {
     return userPackagesDiscoveryTask
-        .measure(() => options.packagesDiscoveryProvider(uri));
+        .measureIo(() => options.packagesDiscoveryProvider(uri));
   }
 
   Uri resolvePatchUri(String libraryName) {
     return backend.resolvePatchUri(libraryName, options.platformConfigUri);
   }
 }
 
 class _Environment implements Environment {
   final Map<String, String> definitions;
 
@@ skipping 31 matching lines @@
   }
 }
 
 /// For every 'dart:' library, a corresponding environment variable is set
 /// to "true". The environment variable's name is the concatenation of
 /// this prefix and the name (without the 'dart:'.
 ///
 /// For example 'dart:html' has the environment variable 'dart.library.html' set
 /// to "true".
 const String _dartLibraryEnvironmentPrefix = 'dart.library.';