Add fine-grained logging for long running transformers.

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';
 import '../asset/asset_node.dart';
 import '../asset/asset_node_set.dart';
 import '../errors.dart';
 import '../log.dart';
 import '../transformer/aggregate_transform.dart';
 import '../transformer/aggregate_transformer.dart';
 import '../transformer/declaring_aggregate_transform.dart';
 import '../transformer/declaring_aggregate_transformer.dart';
 import '../transformer/lazy_aggregate_transformer.dart';
 import '../utils.dart';
 import 'node_status.dart';
 import 'node_streams.dart';
 import 'phase.dart';
 import 'transformer_classifier.dart';
 
+/// Every `_applyLogDuration`, we will issue a fine log entry letting the user
+/// know that the transform is still executing.
+const _applyLogDuration = const Duration(seconds: 10);
+
 /// Describes a transform on a set of assets and its relationship to the build
 /// dependency graph.
 ///
 /// Keeps track of whether it's dirty and needs to be run and which assets it
 /// depends on.
 class TransformNode {
   /// The aggregate key for this node.
   final String key;
 
   /// The [TransformerClassifier] that [this] belongs to.
@@ skipping 128 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;
+  /// Map to track pending requests for secondary inputs.
+  ///
+  /// Keys are the secondary inputs that have been requested but not yet
+  /// produced. Values are the number of requests for that input.
+  final _pendingSecondaryInputs = <AssetId, int>{};
 
   /// 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) {
@@ skipping 383 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++;
+    _pendingSecondaryInputs[id] = _pendingSecondaryInputs.containsKey(id)
+        ? _pendingSecondaryInputs[id] + 1
+        : 1;
     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);
 
         // If this id is for an asset in another package, subscribe to that
         // package's asset cascade so when it starts emitting the id we know to
         // re-run the transformer.
@@ skipping 12 matching lines @@
 
         throw new AssetNotFoundException(id);
       }
 
       _secondarySubscriptions.putIfAbsent(node.id, () {
         return node.onStateChange.listen((_) => _dirty());
       });
 
       return node.asset;
     }).whenComplete(() {
-      _pendingSecondaryInputs--;
-      if (_pendingSecondaryInputs != 0) _timeAwaitingInputs.stop();
+      assert(_pendingSecondaryInputs.containsKey(id));
+      if (_pendingSecondaryInputs[id] == 1) {
+        _pendingSecondaryInputs.remove(id);
+      } else {
+        _pendingSecondaryInputs[id]--;
+      }
+      if (_pendingSecondaryInputs.isEmpty) _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();
 
+    var transformCounterTimer;
+
     return syncFuture(() {
       _timeInTransformer.reset();
       _timeAwaitingInputs.reset();
       _timeInTransformer.start();
+
+      transformCounterTimer = new Timer.periodic(_applyLogDuration, (_) {
+        if (_streams.onLogController.isClosed ||
+            !_timeInTransformer.isRunning) {
+          return;
+        }
+
+        var message = new StringBuffer("Not yet complete after "
+            "${niceDuration(_timeInTransformer.elapsed)}");
+        if (_pendingSecondaryInputs.isNotEmpty) {
+          message.write(", waiting on input(s) "
+              "${_pendingSecondaryInputs.keys.join(", ")}");
+        }
+        _streams.onLogController.add(new LogEntry(
+              info,
+              info.primaryId,
+              LogLevel.FINE,
+              message.toString(),
+              null));
+      });
+
       return transformer.apply(controller.transform);
     }).whenComplete(() {
+      transformCounterTimer.cancel();
       _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);
@@ skipping 230 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;
 }