Revamped terminal output for update.

Revamped terminal output for update.

Features:

- Non-verbose output is now limited to a one-line progress
indicator.

- Verbose output is now collated per subprocess.  As soon as a
subprocess finishes, its full output is dumped to terminal.

- Verbose output is prefixed with timestamps representing elapsed
time since the beginning of the gclient invocation.

- git progress indicators ("Receiving objects", etc.) are limited to
one line every 10 seconds.

- In both verbose and non-verbose mode, if a failure occurs, the
full output of the failed update operation is dumped to terminal
just before exit.

- In the event that updates are progressing, but slowly,
"Still working" messages will be printed periodically, to pacify
users and buildbots.

BUG=361351
R=hinoka@google.com

Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=262500

[szager1, 2014-04-05 23:19:06]

Hey folks,

I'm sending this to a lot of reviewers because it's a big change.  This
completely revamps the terminal output for git-based gclient.  In addition to
the advantages listed in the change description, this should make it possible to
diagnose errors and performance bottlenecks in our windows/msysgit bots.

I still have to fix up all the unit tests, but I wanted to give you all a
preview of the changes.  I recommend you try downloading and applying the patch,
and then running 'gclient sync' with various options (with/without '-v',
with/without '-j 1', etc.).

[szager1, 2014-04-07 07:30:35]

Tests now pass.

[szager1, 2014-04-07 16:21:05]

I manually installed this patch onto the chromium.git win builder, vm402-m1. 
Here's an example of what the new output looks like:

http://chromegw/i/chromium.git/builders/WinGit/builds/4124/steps/bot_update/l...

[agable, 2014-04-07 19:11:52]

On 2014/04/07 16:21:05, szager1 wrote:
> I manually installed this patch onto the chromium.git win builder, vm402-m1. 
> Here's an example of what the new output looks like:
> 
>
http://chromegw/i/chromium.git/builders/WinGit/builds/4124/steps/bot_update/l...

Regarding the git-cache failures in that log:
Ctrl+F for 'filename'
1st set of occurrences: Unclear why this fails. The failure is in the git-cache
bash wrapper itself. However it clearly succeeded just seconds before (when
git-cache populate was called) and it succeeds many more times later.
2nd set of occurrences: This is just gclient printing out the full log as it
dumps the error.
3rd set of occurrences: Gclient retries syncing 'src'. The first call to
'git-cache populate' fails, and prints the filename error. However, that
subprocess call (line 711 of gclient_scm) has retry=True, so it silently retries
and succeeds, thus printing out the standard git-cache populate text.
4th occurrence: unrelated.

[Ryan Tseng, 2014-04-07 20:56:38]

This looks good to me, and I think is land-able (% nits) given that the smoke
test pass and the demo looks okay.

The main comments are (can be addressed in this CL or a followup CL):
* There are a lot of [0:08:28] Still working... messages that don't seem to have
a backstory.
* Work Items should also be annotated with start/end/elapsed time.
* The above info (Work item -> elapsed time) should be exposed in the output
json.

https://codereview.chromium.org/227163002/diff/20001/gclient_utils.py
File gclient_utils.py (right):

https://codereview.chromium.org/227163002/diff/20001/gclient_utils.py#newcode760
gclient_utils.py:760: def out_cb(self, _):
What does "cb" stand for?

https://codereview.chromium.org/227163002/diff/20001/gclient_utils.py#newcode773
gclient_utils.py:773: task.name, comment, task.outbuf.getvalue())
trim task.outbuf.getvalue(), there seems to be an extraneous newline at the end
of the output

[0:07:42] HEAD is now at 2880170 Get rid of old keychain_reauthorize files.
[0:10:13] Checked out revision 28801705318615693b5688d036f7f5261498a418

---------------------------------------- 

Also annotating this with start/end/elapsed time would be useful, since there
are some tasks that don't print anything and we have no insight on how long they
take.

https://codereview.chromium.org/227163002/diff/20001/gclient_utils.py#newcode813
gclient_utils.py:813: now = datetime.datetime.now()
nit: time.time()? To match timekeeping style earlier in GitFilter()

https://codereview.chromium.org/227163002/diff/20001/gclient_utils.py#newcode818
gclient_utils.py:818: print >> sys.stdout, '[%s] Still working...' % Elapsed()
Not always clear what process is causing this to print out "still working"
sometimes, especially if its after the end of a process and before another one
starts.

...
---------------------------------------- 
[0:02:08] Still working...
[0:02:18] Still working...
<...snip...>
[0:05:18] Still working...
[0:05:20] Still working...

src/chrome/browser/google/linkdoctor_internal
----------------------------------------

Maybe add in a list of what's currently being worked on:
Still working on [this, that, foo, bar, ...]...

https://codereview.chromium.org/227163002/diff/20001/gclient_utils.py#newcode841
gclient_utils.py:841: sys.stdout.write('\n')
nit: print >> sys.stdout, '', to match print style in surrounding lines.

https://codereview.chromium.org/227163002/diff/20001/gclient_utils.py#newcode862
gclient_utils.py:862: print >> sys.stdout, self.format_task_output(t.item)
I think it'd be useful to also print the # of minutes elapse this therad took.

[Dirk Pranke, 2014-04-08 01:50:05]

drive-by comments ... this idea looks like a big improvement over the existing
state of affairs, so I'm looking forward to it landing.

I have a vague dream where all of our long-running tools and binaries move to a
more ninja-like form of output so that things can be consistently parseable. 

I think this could be converted over fairly easily and made a bit terse, but I
probably wouldn't suggest doing this as part of this CL.

If others thought this would be useful, I'd be happy to file a separate bug for
such a thing and discuss thoughts there.

[szager1, 2014-04-08 20:41:14]

Nits scratched, PTAL.

https://codereview.chromium.org/227163002/diff/20001/gclient_utils.py
File gclient_utils.py (right):

https://codereview.chromium.org/227163002/diff/20001/gclient_utils.py#newcode760
gclient_utils.py:760: def out_cb(self, _):
On 2014/04/07 20:56:38, Ryan T. wrote:
> What does "cb" stand for?

CallBack

https://codereview.chromium.org/227163002/diff/20001/gclient_utils.py#newcode773
gclient_utils.py:773: task.name, comment, task.outbuf.getvalue())
On 2014/04/07 20:56:38, Ryan T. wrote:
> trim task.outbuf.getvalue(), there seems to be an extraneous newline at the
end
> of the output
> 
> [0:07:42] HEAD is now at 2880170 Get rid of old keychain_reauthorize files.
> [0:10:13] Checked out revision 28801705318615693b5688d036f7f5261498a418
> 
> ---------------------------------------- 
> 
> Also annotating this with start/end/elapsed time would be useful, since there
> are some tasks that don't print anything and we have no insight on how long
they
> take.

Done.

https://codereview.chromium.org/227163002/diff/20001/gclient_utils.py#newcode813
gclient_utils.py:813: now = datetime.datetime.now()
On 2014/04/07 20:56:38, Ryan T. wrote:
> nit: time.time()? To match timekeeping style earlier in GitFilter()

Nice thing about datetime is the elegant arithmetic:

start = datetime.now()
do_stuff()
end = datetime.now()
elapsed = end - start  # elapsed is an instance of datetime.timedelta

timedelta objects have a nice default string representation.

https://codereview.chromium.org/227163002/diff/20001/gclient_utils.py#newcode818
gclient_utils.py:818: print >> sys.stdout, '[%s] Still working...' % Elapsed()
On 2014/04/07 20:56:38, Ryan T. wrote:
> Not always clear what process is causing this to print out "still working"
> sometimes, especially if its after the end of a process and before another one
> starts.
> 
> ...
> ---------------------------------------- 
> [0:02:08] Still working...
> [0:02:18] Still working...
> <...snip...>
> [0:05:18] Still working...
> [0:05:20] Still working...
> 
> src/chrome/browser/google/linkdoctor_internal
> ----------------------------------------
> 
> Maybe add in a list of what's currently being worked on:
> Still working on [this, that, foo, bar, ...]...

Done.

https://codereview.chromium.org/227163002/diff/20001/gclient_utils.py#newcode841
gclient_utils.py:841: sys.stdout.write('\n')
On 2014/04/07 20:56:38, Ryan T. wrote:
> nit: print >> sys.stdout, '', to match print style in surrounding lines.

Done.

https://codereview.chromium.org/227163002/diff/20001/gclient_utils.py#newcode862
gclient_utils.py:862: print >> sys.stdout, self.format_task_output(t.item)
On 2014/04/07 20:56:38, Ryan T. wrote:
> I think it'd be useful to also print the # of minutes elapse this therad took.

Done.

[Ryan Tseng, 2014-04-08 20:44:22]

lgtm

[szager1, 2014-04-08 20:50:46]

Committed patchset #5 manually as r262500 (presubmit successful).

[cmp, 2014-04-08 20:56:17]

Stefan, was about to ask you to send a PSA announcing this change, but you just
sent one.  Good work.