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 'commandline_options.dart';
 import 'common.dart';
 import 'common/tasks.dart' show
-    GenericTask;
+    GenericTask,
+    Measurer;
 import 'common/backend_api.dart' show
     Backend;
 import 'compiler.dart';
 import 'diagnostics/diagnostic_listener.dart' show
     DiagnosticOptions;
 import 'diagnostics/messages.dart' show
     Message;
 import 'elements/elements.dart' as elements;
 import 'io/source_file.dart';
 import 'platform_configuration.dart' as platform_configuration;
 import 'script.dart';
 
 const bool forceIncrementalSupport =
     const bool.fromEnvironment('DART2JS_EXPERIMENTAL_INCREMENTAL_SUPPORT');
 
 /// Locations of the platform descriptor files relative to the library root.
 const String _clientPlatform = "lib/dart_client.platform";
 const String _serverPlatform = "lib/dart_server.platform";
 const String _sharedPlatform = "lib/dart_shared.platform";
 const String _dart2dartPlatform = "lib/dart2dart.platform";
 
 /// Implements the [Compiler] using a [api.CompilerInput] for supplying the
 /// sources.
 class CompilerImpl extends Compiler {
-  api.CompilerInput provider;
-  api.CompilerDiagnostics handler;
-  final Uri platformConfigUri;
-  final Uri packageConfig;
-  final Uri packageRoot;
-  final api.PackagesDiscoveryProvider packagesDiscoveryProvider;
-  Packages packages;
-  List<String> options;
-  Map<String, dynamic> environment;
-  bool mockableLibraryUsed = false;
-
-  /// A mapping of the dart: library-names to their location.
-  ///
-  /// Initialized in [setupSdk].
-  Map<String, Uri> sdkLibraries;
-
-  GenericTask userHandlerTask;
-  GenericTask userProviderTask;
-  GenericTask userPackagesDiscoveryTask;
-
-  Uri get libraryRoot => platformConfigUri.resolve(".");
-
+  // Constructor must be first to ensure [Measurer] is instantiated before
+  // other computations.
   CompilerImpl(this.provider,
            api.CompilerOutput outputProvider,
            this.handler,
            Uri libraryRoot,
            this.packageRoot,
            List<String> options,
            this.environment,
            [this.packageConfig,
             this.packagesDiscoveryProvider,
-            Backend makeBackend(Compiler compiler)])
-      : this.options = options,
-        this.platformConfigUri = resolvePlatformConfig(libraryRoot, options),
-        super(
+            Backend makeBackend(Compiler compiler),
+            Measurer measurer])
+      : super( // Call super first to ensure Measurer is instantiated first.

[floitsch, 2016/01/07 14:40:39]

Tbh I would prefer if super stays last, and you just had a factory constructor.
It would make it conceptually clearer too:

factory CompilerImpl(...) {
  // If we don't have a measurer yet, instantiate one now before we do
  // any other work.
  measurer ??= new Measurer();
  return new CompilerImpl._(...);
}

[ahe, 2016/01/08 09:02:01]

Code removed, but FWIW, I can't use a factory constructor as Fletch subclasses
this class.

+            measurer: measurer == null ? new Measurer() : measurer,

[floitsch, 2016/01/07 14:40:39]

measurer ?? new Measurer()

[ahe, 2016/01/08 09:02:01]

Code removed.

             outputProvider: outputProvider,
             enableTypeAssertions: hasOption(options, Flags.enableCheckedMode),
             enableUserAssertions: hasOption(options, Flags.enableCheckedMode),
             trustTypeAnnotations:
                 hasOption(options, Flags.trustTypeAnnotations),
             trustPrimitives:
                 hasOption(options, Flags.trustPrimitives),
             enableMinification: hasOption(options, Flags.minify),
             useFrequencyNamer:
                 !hasOption(options, Flags.noFrequencyBasedMinification),
@@ skipping 37 matching lines @@
                     hasOption(options, Flags.showPackageWarnings)),
             enableExperimentalMirrors:
                 hasOption(options, Flags.enableExperimentalMirrors),
             enableAssertMessage:
                 hasOption(options, Flags.enableAssertMessage),
             generateCodeWithCompileTimeErrors:
                 hasOption(options, Flags.generateCodeWithCompileTimeErrors),
             testMode: hasOption(options, Flags.testMode),
             allowNativeExtensions:
                 hasOption(options, Flags.allowNativeExtensions),
-            makeBackend: makeBackend) {
+            makeBackend: makeBackend),
+        this.options = options,
+        this.platformConfigUri = resolvePlatformConfig(libraryRoot, options) {
     tasks.addAll([
         userHandlerTask = new GenericTask('Diagnostic handler', this),
         userProviderTask = new GenericTask('Input provider', this),
         userPackagesDiscoveryTask =
             new GenericTask('Package discovery', this),
     ]);
     if (libraryRoot == null) {
       throw new ArgumentError("[libraryRoot] is null.");
     }
     if (!libraryRoot.path.endsWith("/")) {
       throw new ArgumentError("[libraryRoot] must end with a /.");
     }
     if (packageRoot != null && packageConfig != null) {
       throw new ArgumentError("Only one of [packageRoot] or [packageConfig] "
                               "may be given.");
     }
     if (packageRoot != null && !packageRoot.path.endsWith("/")) {
       throw new ArgumentError("[packageRoot] must end with a /.");
     }
     if (!analyzeOnly) {
       if (allowNativeExtensions) {
         throw new ArgumentError(
             "${Flags.allowNativeExtensions} is only supported in combination "
             "with ${Flags.analyzeOnly}");
       }
     }
   }
 
+  api.CompilerInput provider;
+  api.CompilerDiagnostics handler;
+  final Uri platformConfigUri;
+  final Uri packageConfig;
+  final Uri packageRoot;
+  final api.PackagesDiscoveryProvider packagesDiscoveryProvider;
+  Packages packages;
+  List<String> options;
+  Map<String, dynamic> environment;
+  bool mockableLibraryUsed = false;
+
+  /// A mapping of the dart: library-names to their location.
+  ///
+  /// Initialized in [setupSdk].
+  Map<String, Uri> sdkLibraries;
+
+  GenericTask userHandlerTask;
+  GenericTask userProviderTask;
+  GenericTask userPackagesDiscoveryTask;
+
+  Uri get libraryRoot => platformConfigUri.resolve(".");
+
   static String extractStringOption(List<String> options,
                                     String prefix,
                                     String defaultValue) {
     for (String option in options) {
       if (option.startsWith(prefix)) {
         return option.substring(prefix.length);
       }
     }
     return defaultValue;
   }
@@ skipping 226 matching lines @@
               node,
               MessageKind.LIBRARY_NOT_FOUND,
               {'resolvedUri': uri});
           return null;
         });
   }
 
   Future<elements.LibraryElement> analyzeUri(
       Uri uri,
       {bool skipLibraryWithPartOfTag: true}) {
-    List<Future> setupFutures = new List<Future>();
-    if (sdkLibraries == null) {
-      setupFutures.add(setupSdk());
-    }
-    if (packages == null) {
-      setupFutures.add(setupPackages(uri));
-    }
-    return Future.wait(setupFutures).then((_) => super.analyzeUri(uri));
+    return new Future(() => (sdkLibraries == null) ? setupSdk() : null)
+        .then((_) => packages == null ? setupPackages(uri) : null)
+        .then((_) => super.analyzeUri(uri));
   }
 
   Future setupPackages(Uri uri) {
     if (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(packageRoot);
     } else if (packageConfig != null) {
       return callUserProvider(packageConfig).then((packageConfigContents) {
         if (packageConfigContents is String) {
@@ skipping 34 matching lines @@
         sdkLibraries = mapping;
       });
     } 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 ${platformConfigUri}');
+    Duration setupDuration = measurer.wallClock.elapsed;
+    return selfTask.measureSubtask("CompilerImpl.run", () {
+      log('Using platform configuration at ${platformConfigUri}');
 
-    return Future.wait([setupSdk(), setupPackages(uri)]).then((_) {
-      assert(sdkLibraries != null);
-      assert(packages != null);
-
-      return super.run(uri).then((bool success) {
-        int cumulated = 0;
+      return setupSdk().then((_) => setupPackages(uri)).then((_) {
+        assert(sdkLibraries != null);
+        assert(packages != null);
+        return super.run(uri);
+      }).then((bool success) {
+        StringBuffer timings = new StringBuffer();
+        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

[floitsch, 2016/01/07 14:40:39]

double is lower case.

[ahe, 2016/01/08 09:02:02]

Done.

+            / 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) {
@@ skipping 28 matching lines @@
       });
     } catch (ex, s) {
       diagnoseCrashInUserCode(
           'Uncaught exception in diagnostic handler', ex, s);
       rethrow;
     }
   }
 
   Future callUserProvider(Uri uri) {
     try {
-      return userProviderTask.measure(() => provider.readFromUri(uri));
+      return userProviderTask.measureIo(() => provider.readFromUri(uri));
     } catch (ex, s) {
       diagnoseCrashInUserCode('Uncaught exception in input provider', ex, s);
       rethrow;
     }
   }
 
   Future<Packages> callUserPackagesDiscovery(Uri uri) {
     try {
-      return userPackagesDiscoveryTask.measure(
+      return userPackagesDiscoveryTask.measureIo(
                  () => packagesDiscoveryProvider(uri));
     } catch (ex, s) {
       diagnoseCrashInUserCode('Uncaught exception in package discovery', ex, s);
       rethrow;
     }
   }
 
   fromEnvironment(String name) => environment[name];
 
   Uri lookupLibraryUri(String libraryName) {
     assert(invariant(NO_LOCATION_SPANNABLE,
         sdkLibraries != null, message: "setupSdk() has not been run"));
     return sdkLibraries[libraryName];
   }
 
   Uri resolvePatchUri(String libraryName) {
     return backend.resolvePatchUri(libraryName, platformConfigUri);
   }
 }