Quantcast

[PATCH 01 of 10 v5] util: introduce timer()

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
16 messages Options
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

[PATCH 01 of 10 v5] util: introduce timer()

Simon Farnsworth
# HG changeset patch
# User Simon Farnsworth <[hidden email]>
# Date 1487188439 28800
#      Wed Feb 15 11:53:59 2017 -0800
# Node ID 36ad17f00656ef853e0bd7b79e9cd98b58c92a16
# Parent  afaf3c2b129c8940387fd9928ae4fdc28259d13c
util: introduce timer()

As documented for timeit.default_timer, there are better timers available for
performance measures on some platforms. These timers don't have a set epoch,
and thus are only useful for interval measurements, but have higher
resolution, and thus get you a better measurement overall.

Use the same selection logic as Python's timeit.default_timer. This is a
platform clock on Python 2 and early Python 3, and time.perf_counter on Python
3.3 and later (where time.perf_counter is introduced as the best timer to use).

diff --git a/mercurial/util.py b/mercurial/util.py
--- a/mercurial/util.py
+++ b/mercurial/util.py
@@ -1203,8 +1203,13 @@
 
 if pycompat.osname == 'nt':
     checkosfilename = checkwinfilename
+    timer = time.clock
 else:
     checkosfilename = platform.checkosfilename
+    timer = time.time
+
+if safehasattr(time, "perf_counter"):
+    timer = time.perf_counter
 
 def makelock(info, pathname):
     try:
_______________________________________________
Mercurial-devel mailing list
[hidden email]
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

[PATCH 02 of 10 v5] mercurial: switch to util.timer for all interval timings

Simon Farnsworth
# HG changeset patch
# User Simon Farnsworth <[hidden email]>
# Date 1487193459 28800
#      Wed Feb 15 13:17:39 2017 -0800
# Node ID 1c71bddbe01e76c1c48b5479ff67d47645afd7b6
# Parent  36ad17f00656ef853e0bd7b79e9cd98b58c92a16
mercurial: switch to util.timer for all interval timings

util.timer is now the best available interval timer, at the expense of not
having a known epoch. Let's use it whenever the epoch is irrelevant.

diff --git a/contrib/hgperf b/contrib/hgperf
old mode 100644
new mode 100755
--- a/contrib/hgperf
+++ b/contrib/hgperf
@@ -55,17 +55,15 @@
 import mercurial.util
 import mercurial.dispatch
 
-import time
-
 def timer(func, title=None):
     results = []
-    begin = time.time()
+    begin = mercurial.util.timer()
     count = 0
     while True:
         ostart = os.times()
-        cstart = time.time()
+        cstart = mercurial.util.timer()
         r = func()
-        cstop = time.time()
+        cstop = mercurial.util.timer()
         ostop = os.times()
         count += 1
         a, b = ostart, ostop
diff --git a/contrib/perf.py b/contrib/perf.py
--- a/contrib/perf.py
+++ b/contrib/perf.py
@@ -190,13 +190,13 @@
 
 def _timer(fm, func, title=None):
     results = []
-    begin = time.time()
+    begin = util.timer()
     count = 0
     while True:
         ostart = os.times()
-        cstart = time.time()
+        cstart = util.timer()
         r = func()
-        cstop = time.time()
+        cstop = util.timer()
         ostop = os.times()
         count += 1
         a, b = ostart, ostop
diff --git a/mercurial/branchmap.py b/mercurial/branchmap.py
--- a/mercurial/branchmap.py
+++ b/mercurial/branchmap.py
@@ -9,7 +9,6 @@
 
 import array
 import struct
-import time
 
 from .node import (
     bin,
@@ -21,6 +20,7 @@
     encoding,
     error,
     scmutil,
+    util,
 )
 
 array = array.array
@@ -261,7 +261,7 @@
         missing heads, and a generator of nodes that are strictly a superset of
         heads missing, this function updates self to be correct.
         """
-        starttime = time.time()
+        starttime = util.timer()
         cl = repo.changelog
         # collect new branch entries
         newbranches = {}
@@ -314,7 +314,7 @@
                     self.tiprev = tiprev
         self.filteredhash = scmutil.filteredhash(repo, self.tiprev)
 
-        duration = time.time() - starttime
+        duration = util.timer() - starttime
         repo.ui.log('branchcache', 'updated %s branch cache in %.4f seconds\n',
                     repo.filtername, duration)
 
diff --git a/mercurial/dispatch.py b/mercurial/dispatch.py
--- a/mercurial/dispatch.py
+++ b/mercurial/dispatch.py
@@ -123,7 +123,7 @@
         return -1
 
     msg = ' '.join(' ' in a and repr(a) or a for a in req.args)
-    starttime = time.time()
+    starttime = util.timer()
     ret = None
     try:
         ret = _runcatch(req)
@@ -135,7 +135,7 @@
                 raise
         ret = -1
     finally:
-        duration = time.time() - starttime
+        duration = util.timer() - starttime
         req.ui.flush()
         req.ui.log("commandfinish", "%s exited %s after %0.2f seconds\n",
                    msg, ret or 0, duration)
diff --git a/mercurial/hook.py b/mercurial/hook.py
--- a/mercurial/hook.py
+++ b/mercurial/hook.py
@@ -9,7 +9,6 @@
 
 import os
 import sys
-import time
 
 from .i18n import _
 from . import (
@@ -88,7 +87,7 @@
                 % (hname, funcname))
 
     ui.note(_("calling hook %s: %s\n") % (hname, funcname))
-    starttime = time.time()
+    starttime = util.timer()
 
     try:
         r = obj(ui=ui, repo=repo, hooktype=name, **args)
@@ -106,7 +105,7 @@
         ui.traceback()
         return True, True
     finally:
-        duration = time.time() - starttime
+        duration = util.timer() - starttime
         ui.log('pythonhook', 'pythonhook-%s: %s finished in %0.2f seconds\n',
                name, funcname, duration)
     if r:
@@ -118,7 +117,7 @@
 def _exthook(ui, repo, name, cmd, args, throw):
     ui.note(_("running hook %s: %s\n") % (name, cmd))
 
-    starttime = time.time()
+    starttime = util.timer()
     env = {}
 
     # make in-memory changes visible to external process
@@ -145,7 +144,7 @@
         cwd = pycompat.getcwd()
     r = ui.system(cmd, environ=env, cwd=cwd)
 
-    duration = time.time() - starttime
+    duration = util.timer() - starttime
     ui.log('exthook', 'exthook-%s: %s finished in %0.2f seconds\n',
            name, cmd, duration)
     if r:
diff --git a/mercurial/profiling.py b/mercurial/profiling.py
--- a/mercurial/profiling.py
+++ b/mercurial/profiling.py
@@ -8,7 +8,6 @@
 from __future__ import absolute_import, print_function
 
 import contextlib
-import time
 
 from .i18n import _
 from . import (
@@ -66,7 +65,7 @@
     collapse_recursion = True
     thread = flamegraph.ProfileThread(fp, 1.0 / freq,
                                       filter_, collapse_recursion)
-    start_time = time.clock()
+    start_time = util.timer()
     try:
         thread.start()
         yield
@@ -74,7 +73,7 @@
         thread.stop()
         thread.join()
         print('Collected %d stack frames (%d unique) in %2.2f seconds.' % (
-            time.clock() - start_time, thread.num_frames(),
+            util.timer() - start_time, thread.num_frames(),
             thread.num_frames(unique=True)))
 
 @contextlib.contextmanager
diff --git a/mercurial/repair.py b/mercurial/repair.py
--- a/mercurial/repair.py
+++ b/mercurial/repair.py
@@ -12,7 +12,6 @@
 import hashlib
 import stat
 import tempfile
-import time
 
 from .i18n import _
 from .node import short
@@ -905,10 +904,10 @@
     # the operation nearly instantaneous and atomic (at least in well-behaved
     # environments).
     ui.write(_('replacing store...\n'))
-    tstart = time.time()
+    tstart = util.timer()
     util.rename(srcrepo.spath, backupvfs.join('store'))
     util.rename(dstrepo.spath, srcrepo.spath)
-    elapsed = time.time() - tstart
+    elapsed = util.timer() - tstart
     ui.write(_('store replacement complete; repository was inconsistent for '
                '%0.1fs\n') % elapsed)
 
diff --git a/mercurial/streamclone.py b/mercurial/streamclone.py
--- a/mercurial/streamclone.py
+++ b/mercurial/streamclone.py
@@ -8,7 +8,6 @@
 from __future__ import absolute_import
 
 import struct
-import time
 
 from .i18n import _
 from . import (
@@ -297,7 +296,7 @@
                        (filecount, util.bytecount(bytecount)))
         handled_bytes = 0
         repo.ui.progress(_('clone'), 0, total=bytecount, unit=_('bytes'))
-        start = time.time()
+        start = util.timer()
 
         # TODO: get rid of (potential) inconsistency
         #
@@ -340,7 +339,7 @@
             # streamclone-ed file at next access
             repo.invalidate(clearfilecache=True)
 
-        elapsed = time.time() - start
+        elapsed = util.timer() - start
         if elapsed <= 0:
             elapsed = 0.001
         repo.ui.progress(_('clone'), None)
diff --git a/mercurial/tags.py b/mercurial/tags.py
--- a/mercurial/tags.py
+++ b/mercurial/tags.py
@@ -14,7 +14,6 @@
 
 import array
 import errno
-import time
 
 from .node import (
     bin,
@@ -344,7 +343,7 @@
         # potentially expensive search.
         return ([], {}, valid, None, True)
 
-    starttime = time.time()
+    starttime = util.timer()
 
     # Now we have to lookup the .hgtags filenode for every new head.
     # This is the most expensive part of finding tags, so performance
@@ -359,7 +358,7 @@
 
     fnodescache.write()
 
-    duration = time.time() - starttime
+    duration = util.timer() - starttime
     ui.log('tagscache',
            '%d/%d cache hits/lookups in %0.4f '
            'seconds\n',
diff --git a/mercurial/util.py b/mercurial/util.py
--- a/mercurial/util.py
+++ b/mercurial/util.py
@@ -2797,13 +2797,13 @@
     '''
 
     def wrapper(*args, **kwargs):
-        start = time.time()
+        start = timer()
         indent = 2
         _timenesting[0] += indent
         try:
             return func(*args, **kwargs)
         finally:
-            elapsed = time.time() - start
+            elapsed = timer() - start
             _timenesting[0] -= indent
             stderr.write('%s%s: %s\n' %
                          (' ' * _timenesting[0], func.__name__,
_______________________________________________
Mercurial-devel mailing list
[hidden email]
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

[PATCH 03 of 10 v5] ui: provide a mechanism to track and log blocked time

Simon Farnsworth
In reply to this post by Simon Farnsworth
# HG changeset patch
# User Simon Farnsworth <[hidden email]>
# Date 1487193465 28800
#      Wed Feb 15 13:17:45 2017 -0800
# Node ID f3a219226ba0658f72801329d07c1ba516152b70
# Parent  1c71bddbe01e76c1c48b5479ff67d47645afd7b6
ui: provide a mechanism to track and log blocked time

We want to log the time Mercurial spends trapped in things outside
programmatic control. Provide a mechanism to give us both command runtime
and as many different sources of blocking as we deem useful.

diff --git a/mercurial/dispatch.py b/mercurial/dispatch.py
--- a/mercurial/dispatch.py
+++ b/mercurial/dispatch.py
@@ -137,6 +137,9 @@
     finally:
         duration = util.timer() - starttime
         req.ui.flush()
+        if req.ui.logblockedtimes:
+            req.ui._blockedtimes['command_duration'] = duration * 1000
+            req.ui.log('uiblocked', 'ui blocked ms', **req.ui._blockedtimes)
         req.ui.log("commandfinish", "%s exited %s after %0.2f seconds\n",
                    msg, ret or 0, duration)
     return ret
diff --git a/mercurial/ui.py b/mercurial/ui.py
--- a/mercurial/ui.py
+++ b/mercurial/ui.py
@@ -7,6 +7,7 @@
 
 from __future__ import absolute_import
 
+import collections
 import contextlib
 import errno
 import getpass
@@ -138,6 +139,8 @@
         self.callhooks = True
         # Insecure server connections requested.
         self.insecureconnections = False
+        # Blocked time
+        self.logblockedtimes = False
 
         if src:
             self.fout = src.fout
@@ -155,6 +158,7 @@
             self.fixconfig()
 
             self.httppasswordmgrdb = src.httppasswordmgrdb
+            self._blockedtimes = src._blockedtimes
         else:
             self.fout = util.stdout
             self.ferr = util.stderr
@@ -164,6 +168,7 @@
             self.environ = encoding.environ
 
             self.httppasswordmgrdb = httppasswordmgrdbproxy()
+            self._blockedtimes = collections.defaultdict(int)
 
         allowed = self.configlist('experimental', 'exportableenviron')
         if '*' in allowed:
@@ -192,6 +197,15 @@
             self._progbar.resetstate()  # reset last-print time of progress bar
         self.httppasswordmgrdb = httppasswordmgrdbproxy()
 
+    @contextlib.contextmanager
+    def timeblockedsection(self, key):
+        starttime = util.timer()
+        try:
+            yield
+        finally:
+            self._blockedtimes[key + '_blocked'] += \
+                (util.timer() - starttime) * 1000
+
     def formatter(self, topic, opts):
         return formatter.formatter(self, topic, opts)
 
@@ -295,6 +309,7 @@
             self._reportuntrusted = self.debugflag or self.configbool("ui",
                 "report_untrusted", True)
             self.tracebackflag = self.configbool('ui', 'traceback', False)
+            self.logblockedtimes = self.configbool('ui', 'logblockedtimes')
 
         if section in (None, 'trusted'):
             # update trust information
diff --git a/tests/test-logtoprocess.t b/tests/test-logtoprocess.t
--- a/tests/test-logtoprocess.t
+++ b/tests/test-logtoprocess.t
@@ -10,6 +10,7 @@
   > def foo(ui, repo):
   >     ui.log('foo', 'a message: %(bar)s\n', bar='spam')
   > EOF
+  $ cp $HGRCPATH $HGRCPATH.bak
   $ cat >> $HGRCPATH << EOF
   > [extensions]
   > logtoprocess=
@@ -52,3 +53,18 @@
   logtoprocess commandfinish output:
   logtoprocess foo output:
   spam
+
+Confirm that logging blocked time catches stdio properly:
+  $ cp $HGRCPATH.bak $HGRCPATH
+  $ cat >> $HGRCPATH << EOF
+  > [extensions]
+  > logtoprocess=
+  > pager=
+  > [logtoprocess]
+  > uiblocked=echo "\$EVENT command \$OPT_COMMAND_DURATION ms"
+  > [ui]
+  > logblockedtimes=True
+  > EOF
+
+  $ hg log
+  uiblocked command [0-9]+.[0-9]* ms (re)
_______________________________________________
Mercurial-devel mailing list
[hidden email]
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

[PATCH 04 of 10 v5] contrib: add a write microbenchmark to perf.py

Simon Farnsworth
In reply to this post by Simon Farnsworth
# HG changeset patch
# User Simon Farnsworth <[hidden email]>
# Date 1487192846 28800
#      Wed Feb 15 13:07:26 2017 -0800
# Node ID 4d0b19ca8a56341fe2a77fd243232185ab4bf5e0
# Parent  f3a219226ba0658f72801329d07c1ba516152b70
contrib: add a write microbenchmark to perf.py

I'm adding some performance logging to ui.write - this benchmark lets us
confirm that the cost of that logging is acceptably low.

At this point, the microbenchmark on Linux over SSH shows:

! wall 3.213560 comb 0.410000 user 0.350000 sys 0.060000 (best of 4)

while on the Mac locally, it shows:

! wall 0.342325 comb 0.180000 user 0.110000 sys 0.070000 (best of 20)

diff --git a/contrib/perf.py b/contrib/perf.py
--- a/contrib/perf.py
+++ b/contrib/perf.py
@@ -1269,6 +1269,17 @@
         timer(fn, title=title)
         fm.end()
 
+@command('perfwrite', formatteropts)
+def perfwrite(ui, repo, **opts):
+    """microbenchmark ui.write
+    """
+    timer, fm = gettimer(ui, opts)
+    def write():
+        for i in range(100000):
+            ui.write(('Testing write performance\n'))
+    timer(write)
+    fm.end()
+
 def uisetup(ui):
     if (util.safehasattr(cmdutil, 'openrevlog') and
         not util.safehasattr(commands, 'debugrevlogopts')):
diff --git a/tests/test-contrib-perf.t b/tests/test-contrib-perf.t
--- a/tests/test-contrib-perf.t
+++ b/tests/test-contrib-perf.t
@@ -109,6 +109,7 @@
    perfvolatilesets
                  benchmark the computation of various volatile set
    perfwalk      (no help text available)
+   perfwrite     microbenchmark ui.write
   
   (use 'hg help -v perfstatusext' to show built-in aliases and global options)
   $ hg perfaddremove
_______________________________________________
Mercurial-devel mailing list
[hidden email]
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

[PATCH 05 of 10 v5] ui: log time spent blocked on stdio

Simon Farnsworth
In reply to this post by Simon Farnsworth
# HG changeset patch
# User Simon Farnsworth <[hidden email]>
# Date 1487195406 28800
#      Wed Feb 15 13:50:06 2017 -0800
# Node ID 1487dd34f44315371738b13519cc4af1c81a7b07
# Parent  4d0b19ca8a56341fe2a77fd243232185ab4bf5e0
ui: log time spent blocked on stdio

We use a wrapper around Mercurial at Facebook that logs key statistics (like
elpased time) to our standard performance tooling.

This is less useful than it could be, because we currently can't tell when a
command is slow because we need to fix Mercurial versus when a command is
slow because the user isn't interacting quickly.

Teach Mercurial to log the time it spends blocked, so that our tooling can
pick it up and submit it with the elapsed time - we can then do the math in
our tooling to see if Mercurial is slow, or if the user simply failed to
interact.

Combining this with the command duration log means that we can ensure that
we concentrate performance efforts on the things that bite Facebook users.

The perfwrite microbenchmark shifts from:
Linux:
! wall 3.213560 comb 0.410000 user 0.350000 sys 0.060000 (best of 4)
Mac:
! wall 0.342325 comb 0.180000 user 0.110000 sys 0.070000 (best of 20)

before this change to:
! wall 3.478070 comb 0.500000 user 0.420000 sys 0.080000 (best of 3)
Mac:
! wall 0.218112 comb 0.220000 user 0.150000 sys 0.070000 (best of 15)

showing a small hit in comb time, but firmly in the noise on wall time.

diff --git a/mercurial/ui.py b/mercurial/ui.py
--- a/mercurial/ui.py
+++ b/mercurial/ui.py
@@ -199,6 +199,7 @@
 
     @contextlib.contextmanager
     def timeblockedsection(self, key):
+        # this is open-coded below - search for timeblockedsection to find them
         starttime = util.timer()
         try:
             yield
@@ -776,31 +777,44 @@
             self._buffers[-1].extend(a for a in args)
         else:
             self._progclear()
-            for a in args:
-                self.fout.write(a)
+            # opencode timeblockedsection because this is a critical path
+            starttime = util.timer()
+            try:
+                for a in args:
+                    self.fout.write(a)
+            finally:
+                self._blockedtimes['stdio_blocked'] += \
+                    (util.timer() - starttime) * 1000
 
     def write_err(self, *args, **opts):
         self._progclear()
         try:
             if self._bufferstates and self._bufferstates[-1][0]:
                 return self.write(*args, **opts)
-            if not getattr(self.fout, 'closed', False):
-                self.fout.flush()
-            for a in args:
-                self.ferr.write(a)
-            # stderr may be buffered under win32 when redirected to files,
-            # including stdout.
-            if not getattr(self.ferr, 'closed', False):
-                self.ferr.flush()
+            with self.timeblockedsection('stdio'):
+                if not getattr(self.fout, 'closed', False):
+                    self.fout.flush()
+                for a in args:
+                    self.ferr.write(a)
+                # stderr may be buffered under win32 when redirected to files,
+                # including stdout.
+                if not getattr(self.ferr, 'closed', False):
+                    self.ferr.flush()
         except IOError as inst:
             if inst.errno not in (errno.EPIPE, errno.EIO, errno.EBADF):
                 raise
 
     def flush(self):
-        try: self.fout.flush()
-        except (IOError, ValueError): pass
-        try: self.ferr.flush()
-        except (IOError, ValueError): pass
+        # opencode timeblockedsection because this is a critical path
+        starttime = util.timer()
+        try:
+            try: self.fout.flush()
+            except (IOError, ValueError): pass
+            try: self.ferr.flush()
+            except (IOError, ValueError): pass
+        finally:
+            self._blockedtimes['stdio_blocked'] += \
+                (util.timer() - starttime) * 1000
 
     def _isatty(self, fh):
         if self.configbool('ui', 'nontty', False):
@@ -962,7 +976,8 @@
         sys.stdout = self.fout
         # prompt ' ' must exist; otherwise readline may delete entire line
         # - http://bugs.python.org/issue12833
-        line = raw_input(' ')
+        with self.timeblockedsection('stdio'):
+            line = raw_input(' ')
         sys.stdin = oldin
         sys.stdout = oldout
 
@@ -1042,13 +1057,14 @@
             self.write_err(self.label(prompt or _('password: '), 'ui.prompt'))
             # disable getpass() only if explicitly specified. it's still valid
             # to interact with tty even if fin is not a tty.
-            if self.configbool('ui', 'nontty'):
-                l = self.fin.readline()
-                if not l:
-                    raise EOFError
-                return l.rstrip('\n')
-            else:
-                return getpass.getpass('')
+            with self.timeblockedsection('stdio'):
+                if self.configbool('ui', 'nontty'):
+                    l = self.fin.readline()
+                    if not l:
+                        raise EOFError
+                    return l.rstrip('\n')
+                else:
+                    return getpass.getpass('')
         except EOFError:
             raise error.ResponseExpected()
     def status(self, *msg, **opts):
diff --git a/tests/test-logtoprocess.t b/tests/test-logtoprocess.t
--- a/tests/test-logtoprocess.t
+++ b/tests/test-logtoprocess.t
@@ -61,10 +61,10 @@
   > logtoprocess=
   > pager=
   > [logtoprocess]
-  > uiblocked=echo "\$EVENT command \$OPT_COMMAND_DURATION ms"
+  > uiblocked=echo "\$EVENT stdio \$OPT_STDIO_BLOCKED ms command \$OPT_COMMAND_DURATION ms"
   > [ui]
   > logblockedtimes=True
   > EOF
 
   $ hg log
-  uiblocked command [0-9]+.[0-9]* ms (re)
+  uiblocked stdio [0-9]+.[0-9]* ms command [0-9]+.[0-9]* ms (re)
_______________________________________________
Mercurial-devel mailing list
[hidden email]
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

[PATCH 06 of 10 v5] ui: time calls to ui.system

Simon Farnsworth
In reply to this post by Simon Farnsworth
# HG changeset patch
# User Simon Farnsworth <[hidden email]>
# Date 1487194152 28800
#      Wed Feb 15 13:29:12 2017 -0800
# Node ID 1ae8bc5565b680008d82e93bee9455432b6ba0b2
# Parent  1487dd34f44315371738b13519cc4af1c81a7b07
ui: time calls to ui.system

We want to know when we're blocked on ui.system, and why. Allow the user to
supply a tag - otherwise we record on an unspecific tag derived from cmd.

diff --git a/mercurial/ui.py b/mercurial/ui.py
--- a/mercurial/ui.py
+++ b/mercurial/ui.py
@@ -35,6 +35,9 @@
 
 urlreq = util.urlreq
 
+# for use with str.translate(None, _keepalnum), to keep just alphanumerics
+_keepalnum = ''.join(c for c in map(chr, range(256)) if not c.isalnum())
+
 samplehgrcs = {
     'user':
 """# example user config (see 'hg help config' for more info)
@@ -1146,15 +1149,19 @@
 
         return t
 
-    def system(self, cmd, environ=None, cwd=None, onerr=None, errprefix=None):
+    def system(self, cmd, environ=None, cwd=None, onerr=None, errprefix=None,
+               blockedtag=None):
         '''execute shell command with appropriate output stream. command
         output will be redirected if fout is not stdout.
         '''
+        if blockedtag is None:
+            blockedtag = 'unknown_system_' + cmd.translate(None, _keepalnum)
         out = self.fout
         if any(s[1] for s in self._bufferstates):
             out = self
-        return util.system(cmd, environ=environ, cwd=cwd, onerr=onerr,
-                           errprefix=errprefix, out=out)
+        with self.timeblockedsection(blockedtag):
+            return util.system(cmd, environ=environ, cwd=cwd, onerr=onerr,
+                               errprefix=errprefix, out=out)
 
     def traceback(self, exc=None, force=False):
         '''print exception traceback if traceback printing enabled or forced.
_______________________________________________
Mercurial-devel mailing list
[hidden email]
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

[PATCH 07 of 10 v5] ui: give editor() a tag of its own

Simon Farnsworth
In reply to this post by Simon Farnsworth
# HG changeset patch
# User Simon Farnsworth <[hidden email]>
# Date 1487194680 28800
#      Wed Feb 15 13:38:00 2017 -0800
# Node ID ce6e773a6719fab87fa098021aac72b42709aa33
# Parent  1ae8bc5565b680008d82e93bee9455432b6ba0b2
ui: give editor() a tag of its own

We know that calls to ui.editor() always block on the user's configured editor.
Use a blocking tag that ensures that we don't see a huge variety of editor
options in our logging.

diff --git a/mercurial/ui.py b/mercurial/ui.py
--- a/mercurial/ui.py
+++ b/mercurial/ui.py
@@ -1139,7 +1139,8 @@
 
             self.system("%s \"%s\"" % (editor, name),
                         environ=environ,
-                        onerr=error.Abort, errprefix=_("edit failed"))
+                        onerr=error.Abort, errprefix=_("edit failed"),
+                        blockedtag='editor')
 
             f = open(name)
             t = f.read()
_______________________________________________
Mercurial-devel mailing list
[hidden email]
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

[PATCH 08 of 10 v5] crecord: log blocked time waiting for curses input

Simon Farnsworth
In reply to this post by Simon Farnsworth
# HG changeset patch
# User Simon Farnsworth <[hidden email]>
# Date 1487194446 28800
#      Wed Feb 15 13:34:06 2017 -0800
# Node ID 124f329bc78f53abce06a1e8e6244fcdcc551e34
# Parent  ce6e773a6719fab87fa098021aac72b42709aa33
crecord: log blocked time waiting for curses input

We want to know when we're blocked waiting for the user - log the time spent
waiting in the curses keyboard handlers

diff --git a/mercurial/crecord.py b/mercurial/crecord.py
--- a/mercurial/crecord.py
+++ b/mercurial/crecord.py
@@ -1375,7 +1375,8 @@
             pass
         helpwin.refresh()
         try:
-            helpwin.getkey()
+            with self.ui.timeblockedsection('crecord'):
+                helpwin.getkey()
         except curses.error:
             pass
 
@@ -1392,7 +1393,8 @@
         self.stdscr.refresh()
         confirmwin.refresh()
         try:
-            response = chr(self.stdscr.getch())
+            with self.ui.timeblockedsection('crecord'):
+                response = chr(self.stdscr.getch())
         except ValueError:
             response = None
 
@@ -1412,7 +1414,8 @@
 
 are you sure you want to review/edit and confirm the selected changes [yn]?
 """)
-        response = self.confirmationwindow(confirmtext)
+        with self.ui.timeblockedsection('crecord'):
+            response = self.confirmationwindow(confirmtext)
         if response is None:
             response = "n"
         if response.lower().startswith("y"):
@@ -1655,7 +1658,8 @@
         while True:
             self.updatescreen()
             try:
-                keypressed = self.statuswin.getkey()
+                with self.ui.timeblockedsection('crecord'):
+                    keypressed = self.statuswin.getkey()
                 if self.errorstr is not None:
                     self.errorstr = None
                     continue
_______________________________________________
Mercurial-devel mailing list
[hidden email]
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

[PATCH 09 of 10 v5] extdiff: log time spent in external diff program

Simon Farnsworth
In reply to this post by Simon Farnsworth
# HG changeset patch
# User Simon Farnsworth <[hidden email]>
# Date 1487194446 28800
#      Wed Feb 15 13:34:06 2017 -0800
# Node ID c17e5f194dca47819ca2d636a3c9cfdf02733ba7
# Parent  124f329bc78f53abce06a1e8e6244fcdcc551e34
extdiff: log time spent in external diff program

We can't fix the time external diff programs take to run. Log that duration
for us to remove from any stats we gather

diff --git a/hgext/extdiff.py b/hgext/extdiff.py
--- a/hgext/extdiff.py
+++ b/hgext/extdiff.py
@@ -273,7 +273,7 @@
         cmdline = re.sub(regex, quote, cmdline)
 
         ui.debug('running %r in %s\n' % (cmdline, tmproot))
-        ui.system(cmdline, cwd=tmproot)
+        ui.system(cmdline, cwd=tmproot, blockedtag='extdiff')
 
         for copy_fn, working_fn, mtime in fns_and_mtime:
             if os.lstat(copy_fn).st_mtime != mtime:
_______________________________________________
Mercurial-devel mailing list
[hidden email]
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

[PATCH 10 of 10 v5] histedit: log the time taken to read in the commands list

Simon Farnsworth
In reply to this post by Simon Farnsworth
# HG changeset patch
# User Simon Farnsworth <[hidden email]>
# Date 1487194446 28800
#      Wed Feb 15 13:34:06 2017 -0800
# Node ID b9cf9ffdf15f67b42e87272e2fb328102e8284ba
# Parent  c17e5f194dca47819ca2d636a3c9cfdf02733ba7
histedit: log the time taken to read in the commands list

If we're being fed an external command list from stdin (histedit --commands -),
then the time spent reading stdin is outside our control. Log it.

diff --git a/hgext/histedit.py b/hgext/histedit.py
--- a/hgext/histedit.py
+++ b/hgext/histedit.py
@@ -992,7 +992,8 @@
 
 def _readfile(ui, path):
     if path == '-':
-        return ui.fin.read()
+        with ui.timeblockedsection('histedit'):
+            return ui.fin.read()
     else:
         with open(path, 'rb') as f:
             return f.read()
_______________________________________________
Mercurial-devel mailing list
[hidden email]
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: [PATCH 10 of 10 v5] histedit: log the time taken to read in the commands list

Bryan O'Sullivan

On Wed, Feb 15, 2017 at 2:07 PM, Simon Farnsworth <[hidden email]> wrote:
histedit: log the time taken to read in the commands list

Series looks great. Ship it!

_______________________________________________
Mercurial-devel mailing list
[hidden email]
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: [PATCH 05 of 10 v5] ui: log time spent blocked on stdio

Simon Farnsworth
In reply to this post by Simon Farnsworth
On 15/02/2017 22:06, Simon Farnsworth wrote:

> diff --git a/tests/test-logtoprocess.t b/tests/test-logtoprocess.t
> --- a/tests/test-logtoprocess.t
> +++ b/tests/test-logtoprocess.t
> @@ -61,10 +61,10 @@
>    > logtoprocess=
>    > pager=
>    > [logtoprocess]
> -  > uiblocked=echo "\$EVENT command \$OPT_COMMAND_DURATION ms"
> +  > uiblocked=echo "\$EVENT stdio \$OPT_STDIO_BLOCKED ms command \$OPT_COMMAND_DURATION ms"
>    > [ui]
>    > logblockedtimes=True
>    > EOF
>
>    $ hg log
> -  uiblocked command [0-9]+.[0-9]* ms (re)
> +  uiblocked stdio [0-9]+.[0-9]* ms command [0-9]+.[0-9]* ms (re)

This test works for me locally, but the new regex seems to fail on the
buildbot:
https://buildbot.mercurial-scm.org/builders/hg%20tests/builds/710/steps/run-tests.py%20(python%202.7.10)/logs/stdio

-  uiblocked stdio [0-9]+.[0-9]* ms command [0-9]+.[0-9]* ms (re)
+  uiblocked stdio 0.0138282775879 ms command 31.3360691071 ms

Can anyone see what I've done wrong? The regex is supposed to remove the
times, but clearly doesn't in some cases.

--
Simon Farnsworth
_______________________________________________
Mercurial-devel mailing list
[hidden email]
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: [PATCH 10 of 10 v5] histedit: log the time taken to read in the commands list

Martin von Zweigbergk via Mercurial-devel
In reply to this post by Bryan O'Sullivan
On Wed, Feb 15, 2017 at 4:05 PM, Bryan O'Sullivan <[hidden email]> wrote:
>
> On Wed, Feb 15, 2017 at 2:07 PM, Simon Farnsworth <[hidden email]> wrote:
>>
>> histedit: log the time taken to read in the commands list
>
>
> Series looks great. Ship it!

Looks like this was queued (by Augie), thanks. I'm working my way
through it now.


>
> _______________________________________________
> Mercurial-devel mailing list
> [hidden email]
> https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
>
_______________________________________________
Mercurial-devel mailing list
[hidden email]
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: [PATCH 09 of 10 v5] extdiff: log time spent in external diff program

Martin von Zweigbergk via Mercurial-devel
In reply to this post by Simon Farnsworth
[+mercurial-devel]

On Thu, Feb 16, 2017 at 2:26 PM, Martin von Zweigbergk
<[hidden email]> wrote:

> On Wed, Feb 15, 2017 at 2:06 PM, Simon Farnsworth <[hidden email]> wrote:
>> # HG changeset patch
>> # User Simon Farnsworth <[hidden email]>
>> # Date 1487194446 28800
>> #      Wed Feb 15 13:34:06 2017 -0800
>> # Node ID c17e5f194dca47819ca2d636a3c9cfdf02733ba7
>> # Parent  124f329bc78f53abce06a1e8e6244fcdcc551e34
>> extdiff: log time spent in external diff program
>>
>> We can't fix the time external diff programs take to run. Log that duration
>> for us to remove from any stats we gather
>
> The commit message seems misleading, or I'm not understanding the
> patch right. IIUC, the time is logged even before this patch, and the
> patch only improve it to say that it's "extdiff" that's taking the
> time. Correct?
>
>>
>> diff --git a/hgext/extdiff.py b/hgext/extdiff.py
>> --- a/hgext/extdiff.py
>> +++ b/hgext/extdiff.py
>> @@ -273,7 +273,7 @@
>>          cmdline = re.sub(regex, quote, cmdline)
>>
>>          ui.debug('running %r in %s\n' % (cmdline, tmproot))
>> -        ui.system(cmdline, cwd=tmproot)
>> +        ui.system(cmdline, cwd=tmproot, blockedtag='extdiff')
>>
>>          for copy_fn, working_fn, mtime in fns_and_mtime:
>>              if os.lstat(copy_fn).st_mtime != mtime:
>> _______________________________________________
>> Mercurial-devel mailing list
>> [hidden email]
>> https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
_______________________________________________
Mercurial-devel mailing list
[hidden email]
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: [PATCH 03 of 10 v5] ui: provide a mechanism to track and log blocked time

Yuya Nishihara
In reply to this post by Simon Farnsworth
On Wed, 15 Feb 2017 14:06:53 -0800, Simon Farnsworth wrote:
> # HG changeset patch
> # User Simon Farnsworth <[hidden email]>
> # Date 1487193465 28800
> #      Wed Feb 15 13:17:45 2017 -0800
> # Node ID f3a219226ba0658f72801329d07c1ba516152b70
> # Parent  1c71bddbe01e76c1c48b5479ff67d47645afd7b6
> ui: provide a mechanism to track and log blocked time

>      finally:
>          duration = util.timer() - starttime
>          req.ui.flush()
> +        if req.ui.logblockedtimes:
> +            req.ui._blockedtimes['command_duration'] = duration * 1000
> +            req.ui.log('uiblocked', 'ui blocked ms', **req.ui._blockedtimes)

[snip]

>              self._reportuntrusted = self.debugflag or self.configbool("ui",
>                  "report_untrusted", True)
>              self.tracebackflag = self.configbool('ui', 'traceback', False)
> +            self.logblockedtimes = self.configbool('ui', 'logblockedtimes')

Just curious. Why this config knob is needed only to suppress the output?
I thought this would stop tracking the blocked time at all.
_______________________________________________
Mercurial-devel mailing list
[hidden email]
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: [PATCH 05 of 10 v5] ui: log time spent blocked on stdio

timeless
In reply to this post by Simon Farnsworth
Simon Farnsworth wrote:
>> -  > uiblocked=echo "\$EVENT command \$OPT_COMMAND_DURATION ms"
>> +  > uiblocked=echo "\$EVENT stdio \$OPT_STDIO_BLOCKED ms command
>> \$OPT_COMMAND_DURATION ms"

For reference, what you've missed was this part.
The part below was fine, but here, you can clearly see it changed from
`command` to stdio`.

had the diff used a smaller -U value, it would have accepted the second change.
This happens to me all the time. I've been meaning to teach the test
harness to be smarter  about differences :/
_______________________________________________
Mercurial-devel mailing list
[hidden email]
https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
Loading...