Automatically log how long each transform runs.

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

 // Copyright (c) 2013, 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 barback.graph.transform_node;
 
 import 'dart:async';
 
 import '../asset/asset.dart';
 import '../asset/asset_id.dart';
@@ skipping 148 matching lines @@
 
   /// The controller for the currently-running [AggregateTransformer.apply]
   /// call's [AggregateTransform].
   ///
   /// This will be non-`null` when [AggregateTransform.apply] is running, which
   /// means that it's always non-`null` when [_state] is [_State.APPLYING] or
   /// [_State.NEEDS_APPLY], sometimes non-`null` when it's
   /// [_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;
 
     _phaseAssetSubscription = phase.previous.onAsset.listen((node) {
       if (!_missingInputs.contains(node.id)) return;
       if (_forced) node.force();
       _dirty();
     });
 
     _phaseStatusSubscription = phase.previous.onStatusChange.listen((status) {
@@ skipping 362 matching lines @@
 
       _state = _State.APPLIED;
       _streams.changeStatus(NodeStatus.IDLE);
     });
   }
 
   /// Gets the asset for an input [id].
   ///
   /// 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
       // results stream.
       if (node == null) {
         _missingInputs.add(id);
         throw new AssetNotFoundException(id);
       }
 
       _secondarySubscriptions.putIfAbsent(node.id, () {
         return node.onStateChange.listen((_) => _dirty());
       });
 
       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();
     });
   }
 
   /// Run [AggregateTransformer.apply].
   ///
   /// Returns whether or not an error occurred while running the transformer.
   Future<bool> _runApply() {
     var controller = new AggregateTransformController(this);
     _applyController = controller;
     _streams.onLogPool.add(controller.onLog);
     for (var primary in _primaries) {
       if (!primary.state.isAvailable) continue;
       controller.addInput(primary.asset);
     }
     _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();
       _applyController = null;
     }).then((_) {
       assert(_state != _State.DECLARED);
       assert(_state != _State.DECLARING);
       assert(_state != _State.APPLIED);
 
       if (!_forced && _primaries.any((node) => !node.state.isAvailable)) {
         _state = _State.DECLARED;
         _streams.changeStatus(NodeStatus.IDLE);
         return false;
       }
 
       if (_isRemoved) return false;
       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) {
       // If the transform became dirty while processing, ignore any errors from
       // it.
       if (_state == _State.NEEDS_APPLY || _isRemoved) return false;
 
       // Catch all transformer errors and pipe them to the results stream. This
       // is so a broken transformer doesn't take down the whole graph.
       phase.cascade.reportError(_wrapException(error, stackTrace));
@@ skipping 183 matching lines @@
   /// declaring and [APPLYING] otherwise. If a primary input is added or
   /// removed, this will transition to [DECLARING].
   static const APPLIED = const _State._("applied");
 
   final String name;
 
   const _State._(this.name);
 
   String toString() => name;
 }