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

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

This also stops logging every successful request in BarbackServer,
since those logs rarely provide value and produce a huge amount of
clutter.

R=rnystrom@google.com

Committed: https://code.google.com/p/dart/source/detail?r=37152

[Bob Nystrom, 2014-06-04 16:44:41]

Instead of doing this one-off in a few places, how about we add support to the
logger to include a time stamp with each logged item? I've written code for that
locally while profiling several times, but never cleaned it up enough to be
worth landing.

This would, of course, be off by default, but could be enabled with something
like --timestamp-log.

What do you think?

[nweiz, 2014-06-04 21:15:48]

On 2014/06/04 16:44:41, Bob Nystrom wrote:
> Instead of doing this one-off in a few places, how about we add support to the
> logger to include a time stamp with each logged item? I've written code for
that
> locally while profiling several times, but never cleaned it up enough to be
> worth landing.
> 
> This would, of course, be off by default, but could be enabled with something
> like --timestamp-log.
> 
> What do you think?

I don't know... I find pure timestamps aren't a great way of quickly learning
how long something takes, since you have to do math. I think in practice we'd
still end up adding ad-hoc logs to print durations since durations are the bits
of information we actually want.

I think it makes sense to take specific performance-sensitive areas and manually
instrument them with duration logic.

[Bob Nystrom, 2014-06-04 23:59:31]

On 2014/06/04 21:15:48, nweiz wrote:
> On 2014/06/04 16:44:41, Bob Nystrom wrote:
> > Instead of doing this one-off in a few places, how about we add support to
the
> > logger to include a time stamp with each logged item? I've written code for
> that
> > locally while profiling several times, but never cleaned it up enough to be
> > worth landing.
> > 
> > This would, of course, be off by default, but could be enabled with
something
> > like --timestamp-log.
> > 
> > What do you think?
> 
> I don't know... I find pure timestamps aren't a great way of quickly learning
> how long something takes, since you have to do math. I think in practice we'd
> still end up adding ad-hoc logs to print durations since durations are the
bits
> of information we actually want.
> 
> I think it makes sense to take specific performance-sensitive areas and
manually
> instrument them with duration logic.

I should have been clearer here. Usually, when I hack this in, I have it print
number of milliseconds elapsed from pub startup.

Having nested duration ranges is nice too, but I find those are a good starting
point.

[nweiz, 2014-06-05 00:42:19]

On 2014/06/04 23:59:31, Bob Nystrom wrote:
> On 2014/06/04 21:15:48, nweiz wrote:
> > On 2014/06/04 16:44:41, Bob Nystrom wrote:
> > > Instead of doing this one-off in a few places, how about we add support to
> the
> > > logger to include a time stamp with each logged item? I've written code
for
> > that
> > > locally while profiling several times, but never cleaned it up enough to
be
> > > worth landing.
> > > 
> > > This would, of course, be off by default, but could be enabled with
> something
> > > like --timestamp-log.
> > > 
> > > What do you think?
> > 
> > I don't know... I find pure timestamps aren't a great way of quickly
learning
> > how long something takes, since you have to do math. I think in practice
we'd
> > still end up adding ad-hoc logs to print durations since durations are the
> bits
> > of information we actually want.
> > 
> > I think it makes sense to take specific performance-sensitive areas and
> manually
> > instrument them with duration logic.
> 
> I should have been clearer here. Usually, when I hack this in, I have it print
> number of milliseconds elapsed from pub startup.
> 
> Having nested duration ranges is nice too, but I find those are a good
starting
> point.

I get it, but I don't think that's a particularly good metric. As soon as you
want to measure a range of times that doesn't start exactly at pub's startup,
you have to do time math, which is gross.

[Bob Nystrom, 2014-06-05 16:20:19]

On 2014/06/05 00:42:19, nweiz wrote:
> On 2014/06/04 23:59:31, Bob Nystrom wrote:
> > On 2014/06/04 21:15:48, nweiz wrote:
> > > On 2014/06/04 16:44:41, Bob Nystrom wrote:
> > > > Instead of doing this one-off in a few places, how about we add support
to
> > the
> > > > logger to include a time stamp with each logged item? I've written code
> for
> > > that
> > > > locally while profiling several times, but never cleaned it up enough to
> be
> > > > worth landing.
> > > > 
> > > > This would, of course, be off by default, but could be enabled with
> > something
> > > > like --timestamp-log.
> > > > 
> > > > What do you think?
> > > 
> > > I don't know... I find pure timestamps aren't a great way of quickly
> learning
> > > how long something takes, since you have to do math. I think in practice
> we'd
> > > still end up adding ad-hoc logs to print durations since durations are the
> > bits
> > > of information we actually want.
> > > 
> > > I think it makes sense to take specific performance-sensitive areas and
> > manually
> > > instrument them with duration logic.
> > 
> > I should have been clearer here. Usually, when I hack this in, I have it
print
> > number of milliseconds elapsed from pub startup.
> > 
> > Having nested duration ranges is nice too, but I find those are a good
> starting
> > point.
> 
> I get it, but I don't think that's a particularly good metric. As soon as you
> want to measure a range of times that doesn't start exactly at pub's startup,
> you have to do time math, which is gross.

Fair enough. I just want something a little more general-purpose. How about
something like:

log.startProfile("a label");

...stuff...

log.endProfile("a label");

That would run a stopwatch for each unique label, and display the elapsed time
when the profile is ended. We'd probably want a different log level for this.

Thoughts?

[nweiz, 2014-06-05 20:07:35]

PTAL

I folded the duration-printing logic into Progress. This has the side benefit of
making progress work better in verbose mode as well.

[Bob Nystrom, 2014-06-05 20:18:17]

https://codereview.chromium.org/311003002/diff/20001/sdk/lib/_internal/pub/li...
File sdk/lib/_internal/pub/lib/src/log.dart (right):

https://codereview.chromium.org/311003002/diff/20001/sdk/lib/_internal/pub/li...
sdk/lib/_internal/pub/lib/src/log.dart:227: /// If anything else is logged
during this (include another call to [progress])
"include" -> "including"

https://codereview.chromium.org/311003002/diff/20001/sdk/lib/_internal/pub/li...
sdk/lib/_internal/pub/lib/src/log.dart:231: Future progress(String message,
Future callback(), {bool fine: false}) {
Instead of a bool for fine, how about just taking a level which defaults to
message?

https://codereview.chromium.org/311003002/diff/20001/sdk/lib/_internal/pub/li...
File sdk/lib/_internal/pub/lib/src/progress.dart (right):

https://codereview.chromium.org/311003002/diff/20001/sdk/lib/_internal/pub/li...
sdk/lib/_internal/pub/lib/src/progress.dart:36: bool animate =
!log.isLevelVisible(log.Level.FINE) &&
Document this.

https://codereview.chromium.org/311003002/diff/20001/sdk/lib/_internal/pub/li...
sdk/lib/_internal/pub/lib/src/progress.dart:50: /// Returns the complete final
progress message.
Delete this.

https://codereview.chromium.org/311003002/diff/20001/sdk/lib/_internal/pub/li...
sdk/lib/_internal/pub/lib/src/progress.dart:54: // If we aren't animating, just
log the final time. This is always
Won't this get logged even if we are animating?

https://codereview.chromium.org/311003002/diff/20001/sdk/lib/_internal/pub/li...
sdk/lib/_internal/pub/lib/src/progress.dart:73:
stdout.writeln("\r$_message...");
What's this for?

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

https://codereview.chromium.org/311003002/diff/20001/sdk/lib/_internal/pub/li...
File sdk/lib/_internal/pub/lib/src/log.dart (right):

https://codereview.chromium.org/311003002/diff/20001/sdk/lib/_internal/pub/li...
sdk/lib/_internal/pub/lib/src/log.dart:227: /// If anything else is logged
during this (include another call to [progress])
On 2014/06/05 20:18:16, Bob Nystrom wrote:
> "include" -> "including"

Done.

https://codereview.chromium.org/311003002/diff/20001/sdk/lib/_internal/pub/li...
sdk/lib/_internal/pub/lib/src/log.dart:227: /// If anything else is logged
during this (include another call to [progress])
On 2014/06/05 20:18:16, Bob Nystrom wrote:
> "include" -> "including"

Done.

https://codereview.chromium.org/311003002/diff/20001/sdk/lib/_internal/pub/li...
sdk/lib/_internal/pub/lib/src/log.dart:231: Future progress(String message,
Future callback(), {bool fine: false}) {
On 2014/06/05 20:18:16, Bob Nystrom wrote:
> Instead of a bool for fine, how about just taking a level which defaults to
> message?

That's how I started doing it, but properly supporting ERROR and WARNING is
weird, since there's no way for us to know if we should be printing the
animation to stderr or not. I figured that for progress bars the only important
distinction was whether or not it was visible by default.

https://codereview.chromium.org/311003002/diff/20001/sdk/lib/_internal/pub/li...
File sdk/lib/_internal/pub/lib/src/progress.dart (right):

https://codereview.chromium.org/311003002/diff/20001/sdk/lib/_internal/pub/li...
sdk/lib/_internal/pub/lib/src/progress.dart:36: bool animate =
!log.isLevelVisible(log.Level.FINE) &&
On 2014/06/05 20:18:16, Bob Nystrom wrote:
> Document this.

Done.

https://codereview.chromium.org/311003002/diff/20001/sdk/lib/_internal/pub/li...
sdk/lib/_internal/pub/lib/src/progress.dart:36: bool animate =
!log.isLevelVisible(log.Level.FINE) &&
On 2014/06/05 20:18:16, Bob Nystrom wrote:
> Document this.

Done.

https://codereview.chromium.org/311003002/diff/20001/sdk/lib/_internal/pub/li...
sdk/lib/_internal/pub/lib/src/progress.dart:50: /// Returns the complete final
progress message.
On 2014/06/05 20:18:16, Bob Nystrom wrote:
> Delete this.

Done.

https://codereview.chromium.org/311003002/diff/20001/sdk/lib/_internal/pub/li...
sdk/lib/_internal/pub/lib/src/progress.dart:54: // If we aren't animating, just
log the final time. This is always
On 2014/06/05 20:18:16, Bob Nystrom wrote:
> Won't this get logged even if we are animating?

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

https://codereview.chromium.org/311003002/diff/20001/sdk/lib/_internal/pub/li...
sdk/lib/_internal/pub/lib/src/progress.dart:73:
stdout.writeln("\r$_message...");
On 2014/06/05 20:18:16, Bob Nystrom wrote:
> What's this for?

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

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

https://codereview.chromium.org/311003002/diff/20001/sdk/lib/_internal/pub/li...
File sdk/lib/_internal/pub/lib/src/progress.dart (right):

https://codereview.chromium.org/311003002/diff/20001/sdk/lib/_internal/pub/li...
sdk/lib/_internal/pub/lib/src/progress.dart:73:
stdout.writeln("\r$_message...");
On 2014/06/05 21:58:19, nweiz wrote:
> On 2014/06/05 20:18:16, Bob Nystrom wrote:
> > What's this for?
> 
> It prevents there being an old, inaccurate time being left on the console.

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]

https://codereview.chromium.org/311003002/diff/20001/sdk/lib/_internal/pub/li...
File sdk/lib/_internal/pub/lib/src/progress.dart (right):

https://codereview.chromium.org/311003002/diff/20001/sdk/lib/_internal/pub/li...
sdk/lib/_internal/pub/lib/src/progress.dart:73:
stdout.writeln("\r$_message...");
On 2014/06/06 20:18:53, Bob Nystrom wrote:
> On 2014/06/05 21:58:19, nweiz wrote:
> > On 2014/06/05 20:18:16, Bob Nystrom wrote:
> > > What's this for?
> > 
> > It prevents there being an old, inaccurate time being left on the console.
> 
> OK, document that.

Done.

> 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?

Done.

[Bob Nystrom, 2014-06-09 20:25:45]

lgtm

[nweiz, 2014-06-10 00:44:29]

Committed patchset #4 manually as r37152 (presubmit successful).