[PATCH 2 of 2] ui: record and print wall clock time

[Bryan O'Sullivan]

On Thu, Feb 2, 2017 at 4:33 PM, Bryan O'Sullivan <bos at serpentine.com> wrote:

> ui: record and print wall clock time
>

This patch is a total hack, but it contains an interesting few nuggets that
it doesn't call out explicitly.

As Simon mentions in one of his patches, we log command performance so that
we can analyse it at scale and identify, and then fix, problems. But
today's simple measure of wallclock time is thrown into confusion by
anything interactive: calls to ssh (might ask for a password), prompts for
input, merges, pagers, you name it.

Measuring CPU time isn't any better, because a cold disk cache can result
in long I/O waits that aren't accounted for, but which a user will
definitely notice. So a wallclock metric that more accurately tracks when
Mercurial is "really doing work" offers significant value.

The current infrastructure for measuring time (when you use "hg --time")
runs as an atexit hook, so it stops counting when Mercurial is about to
exit. Thanks to the pager infrastructure, it's possible to exit long after
we've finished doing any real work, because we're waiting on the pager
child process to quit.

As a quantity to measure, "how long between us starting a timer and the
process exiting" is arguably not (ever?) what we really want. Instead, I
think it's "how long between starting and finishing meaningful work", which
the "wall" figure in the patch above gets closer to. Being able to identify
time spent waiting on I/O or subprocesses (the "io" figure in the patch,
and the main focus of Simon's patches) is another aspect of accurate
counting for doing performance analysis at scale.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.mercurial-scm.org/pipermail/mercurial-devel/attachments/20170202/d5861bb2/attachment.html>