Automatically log how long each transform runs.

Automatically log how long each transform runs.

These logs are fine, so they won't appear unless the user runs pub in
verbose mode. They also won't appear for transformers that take less
than a second to run.

R=rnystrom@google.com
BUG=16946
Committed: https://code.google.com/p/dart/source/detail?r=37912

[Bob Nystrom, 2014-07-01 17:08:36]

Couple of suggestions but LGTM!

https://codereview.chromium.org/368463002/diff/1/pkg/barback/lib/src/graph/tr...
File pkg/barback/lib/src/graph/transform_node.dart (right):

https://codereview.chromium.org/368463002/diff/1/pkg/barback/lib/src/graph/tr...
pkg/barback/lib/src/graph/transform_node.dart:581: if (_pendingSecondaryInputs
!= 0) return;
Nit, but I think this is clearer without an early return:

if (_pendingSecondaryInputs == 0) timeAwaitingInputs.stop();

https://codereview.chromium.org/368463002/diff/1/pkg/barback/lib/src/graph/tr...
pkg/barback/lib/src/graph/transform_node.dart:630: // --verbose" can see it.
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.

https://codereview.chromium.org/368463002/diff/1/pkg/barback/lib/src/graph/tr...
pkg/barback/lib/src/graph/transform_node.dart:634: "Took
${niceDuration(_timeInTransformer.elapsed)} "
Maybe clarify that it was apply() that was timed?

https://codereview.chromium.org/368463002/diff/1/pkg/barback/lib/src/graph/tr...
pkg/barback/lib/src/graph/transform_node.dart:635:
"(${niceDuration(_timeAwaitingInputs.elapsed)} awaiting secondary "
Long line.

[nweiz, 2014-07-01 21:57:09]

https://codereview.chromium.org/368463002/diff/1/pkg/barback/lib/src/graph/tr...
File pkg/barback/lib/src/graph/transform_node.dart (right):

https://codereview.chromium.org/368463002/diff/1/pkg/barback/lib/src/graph/tr...
pkg/barback/lib/src/graph/transform_node.dart:581: if (_pendingSecondaryInputs
!= 0) return;
On 2014/07/01 17:08:35, Bob Nystrom wrote:
> Nit, but I think this is clearer without an early return:
> 
> if (_pendingSecondaryInputs == 0) timeAwaitingInputs.stop();

Done.

https://codereview.chromium.org/368463002/diff/1/pkg/barback/lib/src/graph/tr...
pkg/barback/lib/src/graph/transform_node.dart:630: // --verbose" can see it.
On 2014/07/01 17:08:36, Bob Nystrom wrote:
> 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.

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.

https://codereview.chromium.org/368463002/diff/1/pkg/barback/lib/src/graph/tr...
pkg/barback/lib/src/graph/transform_node.dart:634: "Took
${niceDuration(_timeInTransformer.elapsed)} "
On 2014/07/01 17:08:36, Bob Nystrom wrote:
> Maybe clarify that it was apply() that was timed?

I think it's clear that that's what's going on.

https://codereview.chromium.org/368463002/diff/1/pkg/barback/lib/src/graph/tr...
pkg/barback/lib/src/graph/transform_node.dart:635:
"(${niceDuration(_timeAwaitingInputs.elapsed)} awaiting secondary "
On 2014/07/01 17:08:35, Bob Nystrom wrote:
> Long line.

Done.

[nweiz, 2014-07-01 21:57:53]

Committed patchset #2 manually as r37912 (presubmit successful).