Patchwork D1721: debug: customizable timestamp when printing ui.debug text

login
register
mail settings
Submitter phabricator
Date Dec. 19, 2017, 1:48 a.m.
Message ID <differential-rev-PHID-DREV-wz5mcqjgvicqt7lxzxzy-req@phab.mercurial-scm.org>
Download mbox | patch
Permalink /patch/26344/
State Superseded
Headers show

Comments

phabricator - Dec. 19, 2017, 1:48 a.m.
spectral created this revision.
Herald added a subscriber: mercurial-devel.
Herald added a reviewer: hg-reviewers.

REVISION SUMMARY
  Sometimes users report "X is slow", where X is usually something that has
  some debug output, like `hg push`. Having timestamps as part of the ui.debug()
  output will help identify what they're seeing. The timestamp is customizable
  using [ui]debugtimestampfmt, which accepts any timestamp that
  datetime.strftime() can handle. I'm using datetime.strftime() since it provides
  the %f format, at least on some platforms, and time.strftime() does not; having
  sub-second precision is pretty useful for these messages.

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D1721

AFFECTED FILES
  mercurial/configitems.py
  mercurial/ui.py

CHANGE DETAILS




To: spectral, #hg-reviewers
Cc: mercurial-devel
phabricator - Dec. 19, 2017, 7:46 p.m.
spectral added a comment.


  Someone pointed me at https://bitbucket.org/octobus/mercurial-devel/commits/668806cb43a0 and mentioned discussions on the devel mailing list that I haven't tracked down yet.  Theirs is more complete and probably better than mine, so it would be nice to unify them if possible, at least in configuration.
  
  Since this patch is only touching 'ui.debug()', it's easy to identify places where we write 'ui.debug(' and don't have a \n['"] in the line, and go and check them to see if they're actually attempting single-line output in multiple invocations.  Most of the cases I found were my grep being very simplistic, some I sent patches for in this series because they *should* have had a \n or weren't doing anything, and in the end there was only this one in histedit.py:1189 that I wasn't sure about and didn't touch:
  
    ui.debug('histedit: %s is replaced by %s\n' % (
        node.short(prec), node.short(succs[0])))
    if len(succs) > 1:
        m = 'histedit:                            %s'
        for n in succs[1:]:
            ui.debug(m % node.short(n))
  
  I'll try to track down those mailing list conversations now

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D1721

To: spectral, #hg-reviewers
Cc: mercurial-devel
phabricator - Dec. 19, 2017, 7:50 p.m.
spectral added a comment.


  https://www.mercurial-scm.org/pipermail/mercurial-devel/2017-April/096617.html is the mailing list thread.  Sounds like core is generally negative on the idea, which is disappointing, but OK.    I can drop it easily :)

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D1721

To: spectral, #hg-reviewers
Cc: mercurial-devel
phabricator - Dec. 19, 2017, 8:05 p.m.
quark added a comment.


  FWIW, if you don't have `ts` installed. That's 4 lines in Ruby:
  
    #!/usr/bin/env ruby
    start = Time.now.to_f
    STDIN.each_line do |l|
      puts "#{'%.3f' % (Time.now.to_f - start)} #{l}"
    end

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D1721

To: spectral, #hg-reviewers
Cc: quark, mercurial-devel
phabricator - Dec. 19, 2017, 8:16 p.m.
spectral added a comment.


  I'm not going to recommend to users to "see if you can reproduce the slowness issues while running with `PYTHONUNBUFFERED=1 /usr/bin/hg --debug | ruby -e'start = Time.now.to_f' -e'STDIN.each_line do |l|' -e" puts \"#{'%.3f' % (Time.now.to_f - start)} #{l}\"" -e'end'`"   :)  Yes, we can make a wrapper for that I suppose.

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D1721

To: spectral, #hg-reviewers
Cc: quark, mercurial-devel
phabricator - Dec. 19, 2017, 9:34 p.m.
quark added a comment.


  --profile is wall time by default. I don't really want to debate but, considering the fact `ui.write` also affects what the user sees. This patch might just encourage people to insert more `ui.debug` statements around `ui.write` just for profiling. That does not sound the right approach when you do want profiling.

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D1721

To: spectral, #hg-reviewers
Cc: quark, mercurial-devel

Patch

diff --git a/mercurial/ui.py b/mercurial/ui.py
--- a/mercurial/ui.py
+++ b/mercurial/ui.py
@@ -9,6 +9,7 @@ 
 
 import collections
 import contextlib
+import datetime
 import errno
 import getpass
 import inspect
@@ -440,6 +441,8 @@ 
                 "report_untrusted")
             self.tracebackflag = self.configbool('ui', 'traceback')
             self.logblockedtimes = self.configbool('ui', 'logblockedtimes')
+            self.debugtimestampfmt = self.config('ui', 'debugtimestampfmt',
+                                                 None)
 
         if section in (None, 'trusted'):
             # update trust information
@@ -1394,6 +1397,9 @@ 
         '''
         if self.debugflag:
             opts[r'label'] = opts.get(r'label', '') + ' ui.debug'
+            if self.debugtimestampfmt:
+                now = datetime.datetime.now()
+                self.write(now.strftime(self.debugtimestampfmt), ' ', **opts)
             self.write(*msg, **opts)
 
     def edit(self, text, user, extra=None, editform=None, pending=None,
diff --git a/mercurial/configitems.py b/mercurial/configitems.py
--- a/mercurial/configitems.py
+++ b/mercurial/configitems.py
@@ -971,6 +971,9 @@ 
 coreconfigitem('ui', 'debugger',
     default=None,
 )
+coreconfigitem('ui', 'debugtimestampfmt',
+    default=None,
+)
 coreconfigitem('ui', 'editor',
     default=dynamicdefault,
 )