Automatically log how long each transform runs.

pkg/barback/lib/src/graph/transform_node.dart

Index: pkg/barback/lib/src/graph/transform_node.dart
diff --git a/pkg/barback/lib/src/graph/transform_node.dart b/pkg/barback/lib/src/graph/transform_node.dart
index 901d79e6074038202b20699f01f3801b037dccec..d5950c76391cbd58dcf00fbd268a826c678ce42a 100644
--- a/pkg/barback/lib/src/graph/transform_node.dart
+++ b/pkg/barback/lib/src/graph/transform_node.dart
@@ -166,6 +166,18 @@ class TransformNode {
   /// [_State.NEEDS_DECLARE], and always `null` otherwise.
   AggregateTransformController _applyController;
 
+  /// The number of secondary inputs that have been requested but not yet
+  /// produced.
+  int _pendingSecondaryInputs = 0;
+
+  /// A stopwatch that tracks the total time spent in a transformer's `apply`
+  /// function.
+  final _timeInTransformer = new Stopwatch();
+
+  /// A stopwatch that tracks the time in a transformer's `apply` function spent
+  /// waiting for [getInput] calls to complete.
+  final _timeAwaitingInputs = new Stopwatch();
+
   TransformNode(this.classifier, this.transformer, this.key, this._location) {
     _forced = transformer is! DeclaringAggregateTransformer;
 
@@ -548,6 +560,8 @@ class TransformNode {
   ///
   /// If an input with [id] cannot be found, throws an [AssetNotFoundException].
   Future<Asset> getInput(AssetId id) {
+    _timeAwaitingInputs.start();
+    _pendingSecondaryInputs++;
     return phase.previous.getOutput(id).then((node) {
       // Throw if the input isn't found. This ensures the transformer's apply
       // is exited. We'll then catch this and report it through the proper
@@ -562,6 +576,10 @@ class TransformNode {
       });
 
       return node.asset;
+    }).whenComplete(() {
+      _pendingSecondaryInputs--;
+      if (_pendingSecondaryInputs != 0) return;

[Bob Nystrom, 2014/07/01 17:08:35]

Nit, but I think this is clearer without an early return:

if (_pendingSecondaryInputs == 0) timeAwaitingInputs.stop();

[nweiz, 2014/07/01 21:57:09]

Done.

+      _timeAwaitingInputs.stop();
     });
   }
 
@@ -579,8 +597,14 @@ class TransformNode {
     _maybeFinishApplyController();
 
     return syncFuture(() {
+      _timeInTransformer.reset();
+      _timeAwaitingInputs.reset();
+      _timeInTransformer.start();
       return transformer.apply(controller.transform);
     }).whenComplete(() {
+      _timeInTransformer.stop();
+      _timeAwaitingInputs.stop();
+
       // Cancel the controller here even if `apply` wasn't interrupted. Since
       // the apply is finished, we want to close out the controller's streams.
       controller.cancel();
@@ -600,6 +624,19 @@ class TransformNode {
       if (_state == _State.NEEDS_APPLY) return false;
       if (_state == _State.NEEDS_DECLARE) return false;
       if (controller.loggedError) return true;
+
+      // If the transformer took long enough, log its duration in fine output.
+      // That way it's not always visible, but users running with "pub serve
+      // --verbose" can see it.

[Bob Nystrom, 2014/07/01 17:08:36]

Since it's at FINE anyway, how about either always logging it, or using a
shorter cut-off duration (0.1s?) A whole second is surprisingly long for a
transformer.

[nweiz, 2014/07/01 21:57:09]

I added an additional check that compares the total time to the time spent
waiting for secondary inputs. If that takes longer than 0.2s it will display,
and it will also display if the whole process takes longer than 1s.

The fine output can still get pretty cluttered when there are a bunch of little
transformers running in parallel, especially since enough parallelism can
artificially increase their runtime.

+      if (_timeInTransformer.elapsed > new Duration(seconds: 1)) {
+        _streams.onLogController.add(new LogEntry(
+            info, info.primaryId, LogLevel.FINE,
+            "Took ${niceDuration(_timeInTransformer.elapsed)} "

[Bob Nystrom, 2014/07/01 17:08:36]

Maybe clarify that it was apply() that was timed?

[nweiz, 2014/07/01 21:57:08]

I think it's clear that that's what's going on.

+              "(${niceDuration(_timeAwaitingInputs.elapsed)} awaiting secondary "

[Bob Nystrom, 2014/07/01 17:08:35]

Long line.

[nweiz, 2014/07/01 21:57:08]

Done.

+              "inputs).",
+            null));
+      }
+
       _handleApplyResults(controller);
       return false;
     }).catchError((error, stackTrace) {