Quantcast

[PATCH 1 of 8 v4] mercurial: use best available timer for perf measurements

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

[PATCH 1 of 8 v4] mercurial: use best available timer for perf measurements

Simon Farnsworth
# HG changeset patch
# User Simon Farnsworth <[hidden email]>
# Date 1486994849 28800
#      Mon Feb 13 06:07:29 2017 -0800
# Node ID 88b51cd7e8e3764af542c25d79a33f5cbda37ac6
# Parent  a0e3d808690d57d1c9dff840e0b8ee099526397b
mercurial: use best available timer for perf measurements

As documented for timer.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.

On newer Python (3.3 or later), there's time.perf_counter, which is

diff --git a/contrib/hgperf b/contrib/hgperf
--- 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.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/commands.py b/mercurial/commands.py
--- a/mercurial/commands.py
+++ b/mercurial/commands.py
@@ -2203,7 +2203,7 @@
     if opts.get('force_lock') or opts.get('force_lock'):
         return 0
 
-    now = time.time()
+    now = util.timer()
     held = 0
 
     def report(vfs, name, method):
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
@@ -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:
@@ -2792,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 2 of 8 v4] ui: provide a mechanism to track and log blocked time

Simon Farnsworth
# HG changeset patch
# User Simon Farnsworth <[hidden email]>
# Date 1486994849 28800
#      Mon Feb 13 06:07:29 2017 -0800
# Node ID 00f01e9a24bc050ab5cbbfc5a8dc99e992e31d2b
# Parent  88b51cd7e8e3764af542c25d79a33f5cbda37ac6
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
@@ -120,6 +121,8 @@
         self.callhooks = True
         # Insecure server connections requested.
         self.insecureconnections = False
+        # Blocked time
+        self.logblockedtimes = False
 
         if src:
             self.fout = src.fout
@@ -137,6 +140,7 @@
             self.fixconfig()
 
             self.httppasswordmgrdb = src.httppasswordmgrdb
+            self._blockedtimes = src._blockedtimes
         else:
             self.fout = util.stdout
             self.ferr = util.stderr
@@ -146,6 +150,7 @@
             self.environ = encoding.environ
 
             self.httppasswordmgrdb = urlreq.httppasswordmgrwithdefaultrealm()
+            self._blockedtimes = collections.defaultdict(lambda: 0)
 
         allowed = self.configlist('experimental', 'exportableenviron')
         if '*' in allowed:
@@ -174,6 +179,14 @@
             self._progbar.resetstate()  # reset last-print time of progress bar
         self.httppasswordmgrdb = urlreq.httppasswordmgrwithdefaultrealm()
 
+    @contextlib.contextmanager
+    def timeblockedsection(self, key):
+        starttime = util.timer()
+        yield
+        duration = (util.timer() - starttime) * 1000
+        key += '_blocked'
+        self._blockedtimes[key] += duration
+
     def formatter(self, topic, opts):
         return formatter.formatter(self, topic, opts)
 
@@ -277,6 +290,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 stdio \$OPT_STDIO_BLOCKED ms command \$OPT_COMMAND_DURATION ms"
+  > [ui]
+  > logblockedtimes=True
+  > EOF
+
+  $ hg log
+  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 3 of 8 v4] 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 1486994849 28800
#      Mon Feb 13 06:07:29 2017 -0800
# Node ID 5a595ee2509989e440d70eb0e134fea915a0a8d6
# Parent  00f01e9a24bc050ab5cbbfc5a8dc99e992e31d2b
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 4 of 8 v4] 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 1486994849 28800
#      Mon Feb 13 06:07:29 2017 -0800
# Node ID 923dcef529e523b391e26840cfa9ea6fd53c4131
# Parent  5a595ee2509989e440d70eb0e134fea915a0a8d6
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 to:
Linux:
! wall 3.316087 comb 0.900000 user 0.810000 sys 0.090000 (best of 3)
Mac:
! wall 0.939282 comb 0.580000 user 0.470000 sys 0.110000 (best of 8)

If I open-code timings in ui.write instead of using the context manager, I see:
Linux:
! 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)

diff --git a/mercurial/ui.py b/mercurial/ui.py
--- a/mercurial/ui.py
+++ b/mercurial/ui.py
@@ -728,31 +728,34 @@
             self._buffers[-1].extend(a for a in args)
         else:
             self._progclear()
-            for a in args:
-                self.fout.write(a)
+            with self.timeblockedsection('stdio'):
+                for a in args:
+                    self.fout.write(a)
 
     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
+        with self.timeblockedsection('stdio'):
+            try: self.fout.flush()
+            except (IOError, ValueError): pass
+            try: self.ferr.flush()
+            except (IOError, ValueError): pass
 
     def _isatty(self, fh):
         if self.configbool('ui', 'nontty', False):
@@ -914,7 +917,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
 
@@ -994,13 +998,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):
_______________________________________________
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 5 of 8 v4] ui: log time spent blocked on editor

Simon Farnsworth
In reply to this post by Simon Farnsworth
# HG changeset patch
# User Simon Farnsworth <[hidden email]>
# Date 1486994849 28800
#      Mon Feb 13 06:07:29 2017 -0800
# Node ID 74a43a6466712c42799528a25c4ca74eb2d25919
# Parent  923dcef529e523b391e26840cfa9ea6fd53c4131
ui: log time spent blocked on editor

The user's editor is outside our control. Log how long we spend blocked on
it.

diff --git a/mercurial/ui.py b/mercurial/ui.py
--- a/mercurial/ui.py
+++ b/mercurial/ui.py
@@ -1075,13 +1075,14 @@
 
             editor = self.geteditor()
 
-            self.system("%s \"%s\"" % (editor, name),
-                        environ=environ,
-                        onerr=error.Abort, errprefix=_("edit failed"))
+            with self.timeblockedsection('editor'):
+                self.system("%s \"%s\"" % (editor, name),
+                            environ=environ,
+                            onerr=error.Abort, errprefix=_("edit failed"))
 
-            f = open(name)
-            t = f.read()
-            f.close()
+                f = open(name)
+                t = f.read()
+                f.close()
         finally:
             os.unlink(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 6 of 8 v4] 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 1486994849 28800
#      Mon Feb 13 06:07:29 2017 -0800
# Node ID 67a55b66a69520f84552cf3c1a7d93202c3f43da
# Parent  74a43a6466712c42799528a25c4ca74eb2d25919
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 7 of 8 v4] 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 1486994849 28800
#      Mon Feb 13 06:07:29 2017 -0800
# Node ID 0727b4d77849fbefbf1ce1de6d9fe22ad2c5e1bd
# Parent  67a55b66a69520f84552cf3c1a7d93202c3f43da
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,8 @@
         cmdline = re.sub(regex, quote, cmdline)
 
         ui.debug('running %r in %s\n' % (cmdline, tmproot))
-        ui.system(cmdline, cwd=tmproot)
+        with ui.timeblockedsection('extdiff'):
+            ui.system(cmdline, cwd=tmproot)
 
         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 8 of 8 v4] 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 1486994849 28800
#      Mon Feb 13 06:07:29 2017 -0800
# Node ID b7557fd38e32b4d82b992003a242cd2a7c9496c5
# Parent  0727b4d77849fbefbf1ce1de6d9fe22ad2c5e1bd
histedit: log the time taken to read in the commands list

If we're being fed an external command list (histedit --commands), then the
time spent reading that file is out of our control. Log it.

diff --git a/hgext/histedit.py b/hgext/histedit.py
--- a/hgext/histedit.py
+++ b/hgext/histedit.py
@@ -991,11 +991,12 @@
     return goalnew
 
 def _readfile(ui, path):
-    if path == '-':
-        return ui.fin.read()
-    else:
-        with open(path, 'rb') as f:
-            return f.read()
+    with ui.timeblockedsection('histedit'):
+        if path == '-':
+            return ui.fin.read()
+        else:
+            with open(path, 'rb') as f:
+                return f.read()
 
 def _validateargs(ui, repo, state, freeargs, opts, goal, rules, revs):
     # TODO only abort if we try to histedit mq patches, not just
_______________________________________________
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 4 of 8 v4] ui: log time spent blocked on stdio

Bryan O'Sullivan
In reply to this post by Simon Farnsworth

On Mon, Feb 13, 2017 at 9:29 AM, Simon Farnsworth <[hidden email]> wrote:
The perfwrite microbenchmark shifts to:
Linux:
! wall 3.316087 comb 0.900000 user 0.810000 sys 0.090000 (best of 3)
Mac:
! wall 0.939282 comb 0.580000 user 0.470000 sys 0.110000 (best of 8)

If I open-code timings in ui.write instead of using the context manager, I see:
Linux:
! 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)


Thanks for adding this data. (For future reference, it's good to include an analysis of the difference instead of just the plain numbers, as I have to flip back and forth between two emails and memorize the numbers to do the comparison in my head.)

These numbers suggest to me that open-coding the performance measurement is the right thing to do for ui.write and ui.flush.

Here's why.

First, let's discount the wall time, as this number is so noisy as to make no sense. For example, if you compare the uninstrumented code with the numbers above, you'll see that wall time has *dropped* by 30% or so on OSX, even though we're doing more work. This is a good object lesson in why contrib/perf.py is very far from a trustworthy benchmarking tool :-)

If you look instead at the somewhat less suspect "comb" time (user+system combined), you'll see that it more than doubles under the context manager, vs a smallish bump with open coding of the measurements.

With its fancy templating and colour support, Mercurial is already surprisingly slow at simply writing to stdout, an activity that is obviously on the critical path for many uses. I believe it's worth the few extra lines of code to keep the lowest-level part of this as fast as possible.

_______________________________________________
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 8 of 8 v4] histedit: log the time taken to read in the commands list

Bryan O'Sullivan
In reply to this post by Simon Farnsworth

On Mon, Feb 13, 2017 at 9:29 AM, Simon Farnsworth <[hidden email]> wrote:
histedit: log the time taken to read in the commands list

If we're being fed an external command list (histedit --commands), then the
time spent reading that file is out of our control. Log it.

I don't think it's worth measuring this, and this patch can reasonably be dropped.

_______________________________________________
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 7 of 8 v4] extdiff: log time spent in external diff program

Bryan O'Sullivan
In reply to this post by Simon Farnsworth

On Mon, Feb 13, 2017 at 9:29 AM, Simon Farnsworth <[hidden email]> wrote:
+        with ui.timeblockedsection('extdiff'):
+            ui.system(cmdline, cwd=tmproot)

Why not simply instrument ui.system directly, and leave its callers untouched?

_______________________________________________
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 2 of 8 v4] ui: provide a mechanism to track and log blocked time

Bryan O'Sullivan
In reply to this post by Simon Farnsworth

On Mon, Feb 13, 2017 at 9:29 AM, Simon Farnsworth <[hidden email]> wrote:
+        duration = (util.timer() - starttime) * 1000
+        key += '_blocked'
+        self._blockedtimes[key] += duration

Could be a one-liner, which will have a tiny but positive impact on perf:

self._blockedtimes[key + '_blocked'] += (util.timer() - starttime) * 1000

_______________________________________________
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 1 of 8 v4] mercurial: use best available timer for perf measurements

Bryan O'Sullivan
In reply to this post by Simon Farnsworth

On Mon, Feb 13, 2017 at 9:29 AM, Simon Farnsworth <[hidden email]> wrote:
mercurial: use best available timer for perf measurements

Thanks for iterating on this patch series so quickly. After you're done with my latest round of comments, this series looks great to ship.

_______________________________________________
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 4 of 8 v4] ui: log time spent blocked on stdio

Simon Farnsworth
In reply to this post by Bryan O'Sullivan
On 13/02/2017 18:00, Bryan O'Sullivan wrote:

>
> On Mon, Feb 13, 2017 at 9:29 AM, Simon Farnsworth <[hidden email]
> <mailto:[hidden email]>> wrote:
>
>     The perfwrite microbenchmark shifts to:
>     Linux:
>     ! wall 3.316087 comb 0.900000 user 0.810000 sys 0.090000 (best of 3)
>     Mac:
>     ! wall 0.939282 comb 0.580000 user 0.470000 sys 0.110000 (best of 8)
>
>     If I open-code timings in ui.write instead of using the context
>     manager, I see:
>     Linux:
>     ! 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)
>
>
> Thanks for adding this data. (For future reference, it's good to include
> an analysis of the difference instead of just the plain numbers, as I
> have to flip back and forth between two emails and memorize the numbers
> to do the comparison in my head.)
>
> These numbers suggest to me that open-coding the performance measurement
> is the right thing to do for ui.write and ui.flush.
>
I'll make that change locally, but I'm not going to resubmit for a few
days, to give other interested parties time to weigh in.
--
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 8 of 8 v4] histedit: log the time taken to read in the commands list

Simon Farnsworth
In reply to this post by Bryan O'Sullivan
On 13/02/2017 18:03, Bryan O'Sullivan wrote:

>
> On Mon, Feb 13, 2017 at 9:29 AM, Simon Farnsworth <[hidden email]
> <mailto:[hidden email]>> wrote:
>
>     histedit: log the time taken to read in the commands list
>
>     If we're being fed an external command list (histedit --commands),
>     then the
>     time spent reading that file is out of our control. Log it.
>
>
> I don't think it's worth measuring this, and this patch can reasonably
> be dropped.

I disagree, because the external list can also be fed from stdin.

I'll beef up this commit message to make it clearer.

--
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 7 of 8 v4] extdiff: log time spent in external diff program

Simon Farnsworth
In reply to this post by Bryan O'Sullivan
On 13/02/2017 18:04, Bryan O'Sullivan wrote:

>
> On Mon, Feb 13, 2017 at 9:29 AM, Simon Farnsworth <[hidden email]
> <mailto:[hidden email]>> wrote:
>
>     +        with ui.timeblockedsection('extdiff'):
>     +            ui.system(cmdline, cwd=tmproot)
>
>
> Why not simply instrument ui.system directly, and leave its callers
> untouched?

I want the caller to tell me what tag to apply to this blocking reason,
so that I can account for the blocking in hook.py (where it's running a
non-interactive process) and sshpeer.py (where it's network blocking as
we talk to a server) differently to extdiff.py and filemerge.py (where
it's an interactive process).

I could push the instrumentation into ui.system, conditional on being
passed a tag (with a catch-all for "not tagged") if people think that
would be more useful?

--
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 2 of 8 v4] ui: provide a mechanism to track and log blocked time

Simon Farnsworth
In reply to this post by Bryan O'Sullivan
On 13/02/2017 18:06, Bryan O'Sullivan wrote:

>
> On Mon, Feb 13, 2017 at 9:29 AM, Simon Farnsworth <[hidden email]
> <mailto:[hidden email]>> wrote:
>
>     +        duration = (util.timer() - starttime) * 1000
>     +        key += '_blocked'
>     +        self._blockedtimes[key] += duration
>
>
> Could be a one-liner, which will have a tiny but positive impact on perf:
>
> self._blockedtimes[key + '_blocked'] += (util.timer() - starttime) * 1000

Will change for the next resend.

--
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 1 of 8 v4] mercurial: use best available timer for perf measurements

Pulkit Goyal
In reply to this post by Simon Farnsworth


On Mon, Feb 13, 2017 at 10:59 PM, Simon Farnsworth <[hidden email]> wrote:
# HG changeset patch
# User Simon Farnsworth <[hidden email]>
# Date 1486994849 28800
#      Mon Feb 13 06:07:29 2017 -0800
# Node ID 88b51cd7e8e3764af542c25d79a33f5cbda37ac6
# Parent  a0e3d808690d57d1c9dff840e0b8ee099526397b
mercurial: use best available timer for perf measurements

As documented for timer.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.

On newer Python (3.3 or later), there's time.perf_counter, which is
 
 Looks like you forgot to complete​ the commit message.

diff --git a/contrib/hgperf b/contrib/hgperf
--- 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.mercurial.util.timer()

​Repeated mercurial here. I guess this is due to some auto completion.​

 
         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/commands.py b/mercurial/commands.py
--- a/mercurial/commands.py
+++ b/mercurial/commands.py
@@ -2203,7 +2203,7 @@
     if opts.get('force_lock') or opts.get('force_lock'):
         return 0

-    now = time.time()
+    now = util.timer()
     held = 0

     def report(vfs, name, method):
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
@@ -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:
@@ -2792,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


_______________________________________________
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 1 of 8 v4] mercurial: use best available timer for perf measurements

Simon Farnsworth
On 13/02/2017 18:49, Pulkit Goyal wrote:

>
>
> On Mon, Feb 13, 2017 at 10:59 PM, Simon Farnsworth <[hidden email]
> <mailto:[hidden email]>> wrote:
>
>     # HG changeset patch
>     # User Simon Farnsworth <[hidden email] <mailto:[hidden email]>>
>     # Date 1486994849 28800
>     #      Mon Feb 13 06:07:29 2017 -0800
>     # Node ID 88b51cd7e8e3764af542c25d79a33f5cbda37ac6
>     # Parent  a0e3d808690d57d1c9dff840e0b8ee099526397b
>     mercurial: use best available timer for perf measurements
>
>     As documented for timer.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.
>
>     On newer Python (3.3 or later), there's time.perf_counter, which is
>
>     ​
>
>  Looks like you forgot to complete​ the commit message.

Yep - looks like I damaged this while histediting - will fix up.

>
>     diff --git a/contrib/hgperf b/contrib/hgperf
>     --- 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.mercurial.util.timer()
>
>
> ​Repeated mercurial here. I guess this is due to some auto completion.​
>

Will fix, and make sure the script runs before resubmitting.

<snip rest of diff - no comments from Pulkit>
--
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 4 of 8 v4] ui: log time spent blocked on stdio

Augie Fackler-2
In reply to this post by Bryan O'Sullivan
On Mon, Feb 13, 2017 at 10:00:25AM -0800, Bryan O'Sullivan wrote:

> On Mon, Feb 13, 2017 at 9:29 AM, Simon Farnsworth <[hidden email]> wrote:
>
> > The perfwrite microbenchmark shifts to:
> > Linux:
> > ! wall 3.316087 comb 0.900000 user 0.810000 sys 0.090000 (best of 3)
> > Mac:
> > ! wall 0.939282 comb 0.580000 user 0.470000 sys 0.110000 (best of 8)
> >
> > If I open-code timings in ui.write instead of using the context manager, I
> > see:
> > Linux:
> > ! 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)
> >
> >
> Thanks for adding this data. (For future reference, it's good to include an
> analysis of the difference instead of just the plain numbers, as I have to
> flip back and forth between two emails and memorize the numbers to do the
> comparison in my head.)
>
> These numbers suggest to me that open-coding the performance measurement is
> the right thing to do for ui.write and ui.flush.

+1 on open-coding for perf reasons, maybe make a comment to that
effect so future optimizers don't get overeager.

>
> Here's why.
>
> First, let's discount the wall time, as this number is so noisy as to make
> no sense. For example, if you compare the uninstrumented code with the
> numbers above, you'll see that wall time has *dropped* by 30% or so on OSX,
> even though we're doing more work. This is a good object lesson in why
> contrib/perf.py is very far from a trustworthy benchmarking tool :-)
>
> If you look instead at the somewhat less suspect "comb" time (user+system
> combined), you'll see that it more than doubles under the context manager,
> vs a smallish bump with open coding of the measurements.
>
> With its fancy templating and colour support, Mercurial is already
> surprisingly slow at simply writing to stdout, an activity that is
> obviously on the critical path for many uses. I believe it's worth the few
> extra lines of code to keep the lowest-level part of this as fast as
> possible.

> _______________________________________________
> 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
12
Loading...