Re: [PATCH] ui: add optional timestamp to output

[Pierre-Yves David]

On 04/13/2017 05:56 AM, Gregory Szorc wrote:

On Tue, Apr 11, 2017 at 12:54 PM, Jun Wu > wrote:

Excerpts from Pierre-Yves David's message of 2017-04-11 20:24:00 +0200:
>
> On 04/11/2017 07:49 PM, Bryan O'Sullivan wrote:
> >
> > On Tue, Apr 11, 2017 at 7:15 AM, Augie Fackler 
> > >> wrote:
> >
> > I'm missing some context. Why do we want timestamps in our output
> > like this?
>
> This is useful to audit the timing of various steps when debugging (eg:
> discovery, cache computations, etc…).
>
> (I'm the one behind who motivated Mathieu to write this patch. I need
> this feature on a regular basis)
>
> > That's what the ts command gives us on Linux. I don't think this needs
> > to be integrated into Mercurial proper.
>
> Yes, `ts` can do this. However, piping to `ts` enable buffered output
> for Python (and Mercurial). As a result the timestamp of line has no
> relation with the time it was requested in the code. Sure one can
> request non-buffered output, but at that point there start to be enough
> obstacle than is get in the "complex" territory when requesting a trace
> to a random user.

That's what `stdbuf` solves. I don't think the "ts" feature should be in
core hg, either.

>
> In addition, `tr` won't handle timestamp for buffered and remote output.
>
> So I think this patches has value on its own.


One thing that stdbuf + ts won't give you is correct handling of some
terminal control characters, such as coloring. For example, Clang
doesn't reset terminal attributes (sgr0) around newlines. So when piping
`clang -fcolor-diagnostics` to ts (you need -fcolor-diagnostics b/c
clang will turn off color when not writing to a TTY), the timestamps
printed by ts will be using whatever attributes the last output was
using. This can result in inconsistently colored and difficult-to-read
output.


Actually, the simplest way to get hg to not buffer the pipe is to set 
PYTHONUNBUFFERED, so stdbuf bugs does not matters to much.



However, this deficiency does not apply to Mercurial, as
color.colorlabel() splits by newline and resets terminal attributes
during newline.

The only real benefit I see to having this feature in core is
convenience, built-in support for coloring, and perhaps better
integration with forensic logging. I'm -0 on this feature because I
don't see a compelling need for it at this time.


Another elements is that windows users (with less performance love) do 
not have the 'ts' utility handy, so having our own feature would help them.


That changes is not critical to me for now. So I'm fine if we shelve 
this until we have a more compelling usecase.


Cheers,

--
Pierre-Yves David
___
Mercurial-devel mailing list
Mercurial-devel@mercurial-scm.org
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel

Re: [PATCH] ui: add optional timestamp to output

[Jun Wu]

Excerpts from Pierre-Yves David's message of 2017-04-11 20:24:00 +0200:
> 
> On 04/11/2017 07:49 PM, Bryan O'Sullivan wrote:
> >
> > On Tue, Apr 11, 2017 at 7:15 AM, Augie Fackler  > > wrote:
> >
> > I'm missing some context. Why do we want timestamps in our output
> > like this?
> 
> This is useful to audit the timing of various steps when debugging (eg: 
> discovery, cache computations, etc…).
> 
> (I'm the one behind who motivated Mathieu to write this patch. I need 
> this feature on a regular basis)
> 
> > That's what the ts command gives us on Linux. I don't think this needs
> > to be integrated into Mercurial proper.
> 
> Yes, `ts` can do this. However, piping to `ts` enable buffered output 
> for Python (and Mercurial). As a result the timestamp of line has no 
> relation with the time it was requested in the code. Sure one can 
> request non-buffered output, but at that point there start to be enough 
> obstacle than is get in the "complex" territory when requesting a trace 
> to a random user.

That's what `stdbuf` solves. I don't think the "ts" feature should be in
core hg, either.

> 
> In addition, `tr` won't handle timestamp for buffered and remote output.
> 
> So I think this patches has value on its own.
> 
> Cheers,
> 
___
Mercurial-devel mailing list
Mercurial-devel@mercurial-scm.org
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel

Re: [PATCH] ui: add optional timestamp to output

[Pierre-Yves David]

On 04/11/2017 07:49 PM, Bryan O'Sullivan wrote:


On Tue, Apr 11, 2017 at 7:15 AM, Augie Fackler > wrote:

I'm missing some context. Why do we want timestamps in our output
like this?


This is useful to audit the timing of various steps when debugging (eg: 
discovery, cache computations, etc…).


(I'm the one behind who motivated Mathieu to write this patch. I need 
this feature on a regular basis)



That's what the ts command gives us on Linux. I don't think this needs
to be integrated into Mercurial proper.


Yes, `ts` can do this. However, piping to `ts` enable buffered output 
for Python (and Mercurial). As a result the timestamp of line has no 
relation with the time it was requested in the code. Sure one can 
request non-buffered output, but at that point there start to be enough 
obstacle than is get in the "complex" territory when requesting a trace 
to a random user.


In addition, `tr` won't handle timestamp for buffered and remote output.

So I think this patches has value on its own.

Cheers,

--
Pierre-Yves David
___
Mercurial-devel mailing list
Mercurial-devel@mercurial-scm.org
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel

Re: [PATCH] ui: add optional timestamp to output

[Bryan O'Sullivan]

On Tue, Apr 11, 2017 at 7:15 AM, Augie Fackler  wrote:

> I'm missing some context. Why do we want timestamps in our output like
> this?
>

That's what the ts command gives us on Linux. I don't think this needs to
be integrated into Mercurial proper.
___
Mercurial-devel mailing list
Mercurial-devel@mercurial-scm.org
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel

Re: [PATCH] ui: add optional timestamp to output

[Augie Fackler]

On Tue, Apr 11, 2017 at 10:50:08PM +0900, Matthieu Laneuville wrote:
> # HG changeset patch
> # User Matthieu Laneuville 
> # Date 1489110756 -32400
> #  Fri Mar 10 10:52:36 2017 +0900
> # Node ID f7c69a6deb56c856f6896f4f318fb125c3c5da37
> # Parent  7433b3bc55eebfa9149280339b406bd4cec64efb
> ui: add optional timestamp to output

I'm missing some context. Why do we want timestamps in our output like this?

>
> This patch adds the possibility of having a timestamp prepended to every line.
> For now, the feature is controled by an experimental config flag
> 'debug-timestamp' and format can be changed with debug-timestamp-format 
> (default
> is %H:%M:%S.%f).
>
> The feature is still experimental because is still needs:
> * win32 support,
> * buffer support,
> * label for the timestamp,
> * a final UI.
>
> A possible final UI would be to trigger this when combining '--debug' with
> '--time' or maybe '--debug' and '--profile'. For now we focus on the
> implementation.
>
> diff -r 7433b3bc55ee -r f7c69a6deb56 mercurial/ui.py
> --- a/mercurial/ui.py Mon Mar 06 23:21:27 2017 -0800
> +++ b/mercurial/ui.py Fri Mar 10 10:52:36 2017 +0900
> @@ -164,6 +164,8 @@ class ui(object):
>  self._colormode = None
>  self._terminfoparams = {}
>  self._styles = {}
> +# keeps track of lines start in _prependtimestamp
> +self._startline = {'std':True, 'err':True}
>
>  if src:
>  self.fout = src.fout
> @@ -788,6 +790,32 @@ class ui(object):
>
>  return "".join(self._buffers.pop())
>
> +def _timestampprefix(self):
> +"""Checks config if timestamp prefix should be used and return
> +   format.
> +"""
> +if not self.configbool("experimental", "debug-timestamp"):
> +return None
> +return self.config("experimental", "debug-timestamp-format",
> +   default="%H:%M:%S.f")
> +
> +def _prependtimestamp(self, args, tsformat, stream):
> +"""Adds timestamp at the beginning of new lines. Both stdout and 
> stderr
> +   streams are tracked separately.
> +"""
> +timestamp = util.datestr(format=tsformat)
> +timestamp = self.label(timestamp, 'debug.timestamp.stdout')
> +timestamp += ' '
> +msgs = []
> +for element in args:
> +for piece in element.splitlines(True):
> +if self._startline[stream]:
> +msgs.append(timestamp)
> +msgs.append(piece)
> +self._startline[stream] = piece.endswith('\n')
> +
> +return msgs
> +
>  def write(self, *args, **opts):
>  '''write args to output
>
> @@ -804,6 +832,7 @@ class ui(object):
>  "cmdname.type" is recommended. For example, status issues
>  a label of "status.modified" for modified files.
>  '''
> +tsformat = self._timestampprefix()
>  if self._buffers and not opts.get('prompt', False):
>  if self._bufferapplylabels:
>  label = opts.get('label', '')
> @@ -819,6 +848,8 @@ class ui(object):
>  if self._colormode is not None:
>  label = opts.get('label', '')
>  msgs = [self.label(a, label) for a in args]
> +if tsformat is not None:
> +msgs = self._prependtimestamp(msgs, tsformat, 'std')
>  self._write(*msgs, **opts)
>
>  def _write(self, *msgs, **opts):
> @@ -833,6 +864,7 @@ class ui(object):
>  (util.timer() - starttime) * 1000
>
>  def write_err(self, *args, **opts):
> +tsformat = self._timestampprefix()
>  self._progclear()
>  if self._bufferstates and self._bufferstates[-1][0]:
>  self.write(*args, **opts)
> @@ -845,6 +877,8 @@ class ui(object):
>  if self._colormode is not None:
>  label = opts.get('label', '')
>  msgs = [self.label(a, label) for a in args]
> +if tsformat is not None:
> +msgs = self._prependtimestamp(msgs, tsformat, 'err')
>  self._write_err(*msgs, **opts)
>
>  def _write_err(self, *msgs, **opts):
> diff -r 7433b3bc55ee -r f7c69a6deb56 tests/test-debug-timestamp.t
> --- /dev/null Thu Jan 01 00:00:00 1970 +
> +++ b/tests/test-debug-timestamp.tFri Mar 10 10:52:36 2017 +0900
> @@ -0,0 +1,142 @@
> +  $ hg init
> +  $ touch a
> +  $ touch b
> +
> +Checking when the feature is disabled
> +
> +  $ hg status --config experimental.debug-timestamp=False
> +  ? a
> +  ? b
> +
> +Now after enabling it
> +
> +  $ cat >> $HGRCPATH << EOF
> +  > [experimental]
> +  > debug-timestamp=True
> +  > debug-timestamp-format=%H:%M
> +  > EOF
> +
> +Create an extension to test all cases
> +
> +  $ cat > $TESTTMP/foocommand.py << EOF
> +  > from mercurial import cmdutil
> +  > cmdtable = {}
> +  > command = cmdutil.command(cmdtable)
> +  >
> +  > @command('testsinglestdout', [])