Roll forward revision 37912.

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) _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.
+      var ranLong = _timeInTransformer.elapsed > new Duration(seconds: 1);
+      var ranLongLocally =
+          _timeInTransformer.elapsed - _timeAwaitingInputs.elapsed >
+            new Duration(milliseconds: 200);
+
+      // Report the transformer's timing information if it spent more than 0.2s
+      // doing things other than waiting for its secondary inputs or if it spent
+      // more than 1s in total.
+      if (ranLongLocally || ranLong) {
+        _streams.onLogController.add(new LogEntry(
+            info, info.primaryId, LogLevel.FINE,
+            "Took ${niceDuration(_timeInTransformer.elapsed)} "
+              "(${niceDuration(_timeAwaitingInputs.elapsed)} awaiting "
+              "secondary 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;
 }