Use Zone to correctly measure async operations.

pkg/compiler/lib/src/common/tasks.dart

Index: pkg/compiler/lib/src/common/tasks.dart
diff --git a/pkg/compiler/lib/src/common/tasks.dart b/pkg/compiler/lib/src/common/tasks.dart
index 8a7dcb3283802fc9549be28405fa7063db6dd94c..d06088a703e0797df6e8a791119108fef2b5ebc9 100644
--- a/pkg/compiler/lib/src/common/tasks.dart
+++ b/pkg/compiler/lib/src/common/tasks.dart
@@ -4,6 +4,13 @@
 
 library dart2js.common.tasks;
 
+import 'dart:async' show
+    Future,
+    Zone,
+    ZoneDelegate,
+    ZoneSpecification,
+    runZoned;
+
 import '../common.dart';
 import '../compiler.dart' show
     Compiler;
@@ -19,19 +26,27 @@ class DeferredTask {
   DeferredTask(this.element, this.action);
 }
 
+/// A [CompilerTask] is used to measure where time is spent in the compiler.
+/// The main entry points are [measure] and [measureIo].
 class CompilerTask {
   final Compiler compiler;
   final Stopwatch watch;
   final Map<String, GenericTask> _subtasks = <String, GenericTask>{};
 
+  int asyncCount = 0;
+
   CompilerTask(Compiler compiler)
       : this.compiler = compiler,
         watch = (compiler.verbose) ? new Stopwatch() : null;
 
   DiagnosticReporter get reporter => compiler.reporter;
 
+  Measurer get measurer => compiler.measurer;
+
   String get name => "Unknown task '${this.runtimeType}'";
 
+  bool get isRunning => watch != null && watch.isRunning;

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

fyi: there is a pattern emerging for this: watch?.isRunning == true;

Not saying you should change.

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

Done.

+
   int get timing {
     if (watch == null) return 0;
     int total = watch.elapsedMilliseconds;
@@ -41,31 +56,159 @@ class CompilerTask {
     return total;
   }
 
-  measure(action()) {
-    // In verbose mode when watch != null.
-    if (watch == null) return action();
-    CompilerTask previous = compiler.measuredTask;
-    if (identical(this, previous)) return action();
-    compiler.measuredTask = this;
+  Duration get duration {
+    if (watch == null) return Duration.ZERO;
+    Duration total = watch.elapsed;
+    for (GenericTask subtask in _subtasks.values) {
+      total += subtask.duration;
+    }
+    return total;
+  }
+
+  /// Perform [action] and use [watch] to measure its runtime (including any
+  /// asynchronous callbacks, such as, [Future.then], but excluding code
+  /// measured by other tasks).
+  measure(action()) => watch == null ? action() : measureZoned(action);
+
+  /// Helper method that starts measuring with this [CompilerTask], that is,
+  /// make this task the currently measured task.
+  CompilerTask start() {
+    if (watch == null) return null;
+    CompilerTask previous = measurer.currentTask;
+    measurer.currentTask = this;
     if (previous != null) previous.watch.stop();
+    // Regardless of [previous] is `null` we've returned from the eventloop.
+    measurer.stopAsyncWallClock();
     watch.start();
-    try {
-      return action();
-    } finally {
-      watch.stop();
-      if (previous != null) previous.watch.start();
-      compiler.measuredTask = previous;
+    return previous;
+  }
+
+  /// Helper method that stops measuring with this [CompilerTask], that is,
+  /// make [previous] the currently measured task.
+  void stop(CompilerTask previous) {
+    if (watch == null) return;
+    watch.stop();
+    if (previous != null) {
+      previous.watch.start();
+    } else {
+      // If there's no previous task, we're about to return control to the
+      // event loop. Start counting that as waiting asynchronous I/O.
+      measurer.startAsyncWallClock();
     }
+    measurer.currentTask = previous;
+  }
+
+  /// Helper method for [measure]. Don't call this method directly as it
+  /// assumes that [watch] isn't null.
+  measureZoned(action()) {
+    // Using zones, we're able to track asynchronous operations correctly, as
+    // our zone will be asked to invoke `then` blocks. Then blocks (the closure
+    // passed to runZoned, and other closures) are run via the `run` functions
+    // below.
+
+    assert(watch != null);
+
+    // The current zone is already measuring `this` task.
+    if (Zone.current[measurer] == this) return action();
+
+    /// Run [f] in [zone]. Running must be delegated to [parent] to ensure that
+    /// various state is set up correctly (in particular in the root

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

in particular `Zone.current`

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

Done.

+    /// zone). Since [measureZoned] can be called recursively (synchronously),
+    /// some of the measuring zones we create will be parents of other
+    /// measuring zones, but we still need to call through the parent
+    /// chain. Consequently, we use a zone value keyed by [measurer] to see if
+    /// we should measure or not when delegating.
+    run(Zone self, ZoneDelegate parent, Zone zone, f()) {
+      if (zone[measurer] != this) return parent.run(zone, f);
+      CompilerTask previous = start();
+      try {
+        return parent.run(zone, f);
+      } finally {
+        stop(previous);
+      }
+    }
+
+    /// Equivalent to [run] except that [f] takes one argument, [arg].

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

nit: s/Equivalent to/Same as/

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

Done.

+    runUnary(Zone self, ZoneDelegate parent, Zone zone, f(arg), arg) {
+      if (zone[measurer] != this) return parent.runUnary(zone, f, arg);
+      CompilerTask previous = start();
+      try {
+        return parent.runUnary(zone, f, arg);
+      } finally {
+        stop(previous);
+      }
+    }
+
+    /// Equivalent to [run] except that [f] takes two arguments ([a1] and [a2]).
+    runBinary(Zone self, ZoneDelegate parent, Zone zone, f(a1, a2), a1, a2) {
+      if (zone[measurer] != this) return parent.runBinary(zone, f, a1, a2);
+      CompilerTask previous = start();
+      try {
+        return parent.runBinary(zone, f, a1, a2);
+      } finally {
+        stop(previous);
+      }
+    }
+
+    return runZoned(
+        action,
+        zoneValues: { measurer: this },
+        zoneSpecification: new ZoneSpecification(
+            run: run, runUnary: runUnary, runBinary: runBinary));
+  }
+
+  /// Asynchronous version of [measure]. Use this when action returns a future
+  /// that's truly asynchronous, such I/O. Only one task can use this method
+  /// concurrently.
+  /// Note: we assume that this method is used only by the compiler input

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

New line before "Note:".

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

Done.

+  /// provider, but it could be used by other tasks as long as the input
+  /// provider will not be called by those tasks.
+  measureIo(Future action()) {
+    return watch == null ? action() : measureIoHelper(action);
   }
 
+  /// Helper method for [measureIo]. Don't call this directly as it assumes
+  /// that [watch] isn't null.
+  Future measureIoHelper(Future action()) {
+    assert(watch != null);
+    if (measurer.currentAsyncTask == null) {
+      measurer.currentAsyncTask = this;
+    } else if (measurer.currentAsyncTask != this) {
+      throw "Can't track async task '$name' because"

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

Generally we avoid throwing just strings.
This looks like a StateError to me.

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

Why?

[floitsch, 2016/01/08 12:07:48]

Long thread on dart-readability, and Bob is in the process of updating the style
guide.

If it's an error, then marking it as such, makes the intent clear. Errors also
have some minor advantages (like capturing the stacktrace).

If it's an exception, then you want a class (probably subclass of Exception), so
that the `catch on X` works.

[ahe, 2016/01/08 12:23:45]

I disagree. This error message is harder to read:

Internal error: StateError: Can't track async task 'foo' because 'bar' is
already being tracked.

Than this:

Internal error: Can't track async task 'foo' because 'bar' is already being
tracked.

The problem is that "StateError" is irrelevant to the problem, yet people have a
tendency to stop reading after they see "StateError". Same argument could be
made for "Internal error" prefix, but we've decided that users need to know
before anything else that they've encountered a bug in the compiler, and they
didn't do anything wrong. As each prefix adds noise, I think it is important to
keep them to a minimum.
That's actually a disadvantage: the automatic stack trace capturing in Error
makes debugging harder in JavaScript. Also, capturing stack traces is
unnecessary since we add the second argument to asynchronous error handlers.

+          " '${measurer.currentAsyncTask.name}' is already being tracked.";
+    }
+    asyncCount++;
+    return measure(action).whenComplete(() {
+      asyncCount--;
+      if (asyncCount == 0) measurer.currentAsyncTask = null;
+    });
+  }
+
+  /// Convenience function for combining
+  /// [DiagnosticReporter.withCurrentElement] and [measure].
   measureElement(Element element, action()) {
-    reporter.withCurrentElement(element, () => measure(action));
+    return watch == null
+        ? reporter.withCurrentElement(element, action)
+        : measureElementHelper(element, action);
+  }
+
+  /// Helper method for [measureElement]. Don't call this directly as it
+  /// assumes that [watch] isn't null.
+  measureElementHelper(Element element, action()) {
+    assert(watch != null);
+    return reporter.withCurrentElement(element, () => measure(action));
   }
 
   /// Measure the time spent in [action] (if in verbose mode) and accumulate it
   /// under a subtask with the given name.
   measureSubtask(String name, action()) {
-    if (watch == null) return action();
+    return watch == null ? action() : measureSubtaskHelper(name, action);
+  }
+
+  /// Helper method for [measureSubtask]. Don't call this directly as it
+  /// assumes that [watch] isn't null.
+  measureSubtaskHelper(String name, action()) {
+    assert(watch != null);
     // Use a nested CompilerTask for the measurement to ensure nested [measure]
     // calls work correctly. The subtasks will never themselves have nested
     // subtasks because they are not accessible outside.
@@ -77,6 +220,8 @@ class CompilerTask {
   Iterable<String> get subtasks => _subtasks.keys;
 
   int getSubtaskTime(String subtask) => _subtasks[subtask].timing;
+
+  bool getSubtaskIsRunning(String subtask) => _subtasks[subtask].isRunning;
 }
 
 class GenericTask extends CompilerTask {
@@ -85,3 +230,51 @@ class GenericTask extends CompilerTask {
   GenericTask(this.name, Compiler compiler)
       : super(compiler);
 }
+
+class Measurer {
+  // Constructor must be first to ensure [wallclock] is started before other

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

I'm not sure I understand the comment. It reads as if the constructor must be
the first thing in the class, but that has obviously no effect on the semantics.

Same for Constructor and ConstructorImpl.

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

This is from the Dart Programming Language Specification, 3rd Edition / June
2015, 10.6.1 Generative Constructors:

"Any initializing formals declared in k’s parameter list are executed in the
order they appear in the program text. Then, k’s initializers are executed in
the order they appear in the program."

(k is the constructor).

I misunderstood this to include variable initializers. However, later on, in
16.12.1 New:

"A fresh instance (10.6.1), i, of class R is allocated. For each instance
variable f of i, if the variable declaration of f has an initializer expression
ef , then ef is evaluated, with the type parameters (if any) of R bound to the
actual type arguments V1,...,Vl, to an object of and f is bound to of. Otherwise
f is bound to null.

[...]

Next, q is executed with this bound to i, the type parameters (if any) of R
bound to the actual type arguments V1, . . . , Vl and the formal parameter
bindings that resulted from the evaluation of the argument list. The result of
the evaluation of e is i."

(q is the constructor)

So the correct solution is actually much simpler and was already implemented:
initializing wallClock should be the first field. I'll move the constructors
back. I'm really happy about this :-)

+  // computations.
+  Measurer()
+      : wallClock = new Stopwatch()..start(),
+        asyncWallClock = new Stopwatch();
+
+  /// Measures the total runtime from this object was constructed.
+  final Stopwatch wallClock;
+
+  /// Measures gaps between zoned closures due to asynchronicity.
+  final Stopwatch asyncWallClock;
+
+  /// The currently running task, that is, the task whose [Stopwatch] is
+  /// currently running.
+  CompilerTask currentTask;
+
+  /// The current task which should be charged for asynchronous gaps.
+  CompilerTask currentAsyncTask;
+
+  /// Start counting the total elapsed time since the compiler started.
+  void startWallClock() {
+    wallClock.start();
+  }
+
+  /// Start counting the total elapsed time since the compiler started.
+  void stopWallClock() {
+    wallClock.stop();
+  }
+
+  /// Call this before returning to the eventloop.
+  void startAsyncWallClock() {
+    if (currentAsyncTask != null) {
+      currentAsyncTask.watch.start();
+    } else {
+      asyncWallClock.start();
+    }
+  }
+
+  /// Call this when the eventloop returns control to us.
+  void stopAsyncWallClock() {
+    if (currentAsyncTask != null) {
+      currentAsyncTask.watch.stop();
+    }
+    asyncWallClock.stop();
+  }
+}