Add instrumentation for tracking how long it takes barback to start.

sdk/lib/_internal/pub/lib/src/progress.dart

Index: sdk/lib/_internal/pub/lib/src/progress.dart
diff --git a/sdk/lib/_internal/pub/lib/src/progress.dart b/sdk/lib/_internal/pub/lib/src/progress.dart
index af7c0afb6e5b534c69817a20705246c69283ca79..dfb938346d17760300a3bbba86a7a5f884f27f2e 100644
--- a/sdk/lib/_internal/pub/lib/src/progress.dart
+++ b/sdk/lib/_internal/pub/lib/src/progress.dart
@@ -22,46 +22,58 @@ class Progress {
   /// progress is done, a single entry will be added to the log for it.
   final String _message;
 
-  Progress(this._message) {
+  /// Whether this should log messages at [log.Level.FINE] rather than
+  /// [log.Level.MESSAGE].
+  final bool _fine;
+
+  /// Gets the current progress time as a parenthesized, formatted string.
+  String get _time => "(${niceDuration(_stopwatch.elapsed)})";
+
+  Progress(this._message, {bool fine: false})
+      : _fine = fine {
     _stopwatch.start();
 
-    if (log.json.enabled) return;
+    bool animate = !log.isLevelVisible(log.Level.FINE) &&

[Bob Nystrom, 2014/06/05 20:18:16]

Document this.

[nweiz, 2014/06/05 21:58:19]

Done.

[nweiz, 2014/06/05 21:58:19]

Done.

+        stdioType(stdout) == StdioType.TERMINAL;
+    (animate || _fine ? log.fine : log.message)("$_message...");
+
+    if (!animate || log.json.enabled) return;
 
-    // Only animate if we're writing to a TTY in human format.
-    if (stdioType(stdout) == StdioType.TERMINAL) {
+    _update();
+    _timer = new Timer.periodic(new Duration(milliseconds: 100), (_) {
       _update();
-      _timer = new Timer.periodic(new Duration(milliseconds: 100), (_) {
-        _update();
-      });
-    } else {
-      stdout.write("$_message... ");
-    }
+    });
   }
 
   /// Stops the progress indicator.
   ///
   /// Returns the complete final progress message.

[Bob Nystrom, 2014/06/05 20:18:16]

Delete this.

[nweiz, 2014/06/05 21:58:19]

Done.

-  String stop() {
+  void stop() {
     _stopwatch.stop();
 
-    // If we aren't animating, just log the final time.
-    if (log.json.enabled) {
-      // Do nothing.
-    } else if (_timer == null) {
-      stdout.writeln(_time);
-    } else {
-      _timer.cancel();
+    // If we aren't animating, just log the final time. This is always

[Bob Nystrom, 2014/06/05 20:18:16]

Won't this get logged even if we are animating?

[nweiz, 2014/06/05 21:58:19]

Yes, it's a little confusingly written. I'll reword it.

+    // [log.fine] because for the most part normal users don't care about the
+    // precise time information beyond what's shown in the animation.
+    log.fine("$_message finished $_time.");
 
-      // Show one final update.
-      _update();
-      stdout.writeln();
-    }
+    if (_timer == null) return;
+    _timer.cancel();
 
-    return "$_message... ${_time}";
+    // Show one final update.
+    _update();
+    stdout.writeln();
   }
 
-  /// Gets the current progress time as a parenthesized, formatted string.
-  String get _time => "(${niceDuration(_stopwatch.elapsed)})";
+  /// Stop animating the progress indicator.
+  ///
+  /// This will continue running the stopwatch so that the full time can be
+  /// logged in [stop].
+  void stopAnimating() {
+    if (_timer == null) return;
+    stdout.writeln("\r$_message...");

[Bob Nystrom, 2014/06/05 20:18:16]

What's this for?

[nweiz, 2014/06/05 21:58:19]

It prevents there being an old, inaccurate time being left on the console.

[Bob Nystrom, 2014/06/06 20:18:53]

OK, document that.

It's confusing because the code in log calls stopAnimating() on all of the
existing progresses, but this code assumes there will only be one currently
animating progress. If there were more than one, their output would step on each
other.

How about changing log so that it distinguishes between the one currently
visible progress and the pool of other non-printing but still running ones?

[nweiz, 2014/06/09 19:55:34]

Done.
Done.

+    _timer.cancel();
+    _timer = null;
+  }
 
   /// Refreshes the progress line.
   void _update() {