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

login
register
mail settings
Submitter Simon Farnsworth
Date Feb. 13, 2017, 5:29 p.m.
Message ID <88b51cd7e8e3764af542.1487006941@devvm022.lla2.facebook.com>
Download mbox | patch
Permalink /patch/18445/
State Changes Requested
Headers show

Comments

Simon Farnsworth - Feb. 13, 2017, 5:29 p.m.
# HG changeset patch
# User Simon Farnsworth <simonfar@fb.com>
# 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
Bryan O'Sullivan - Feb. 13, 2017, 6:07 p.m.
On Mon, Feb 13, 2017 at 9:29 AM, Simon Farnsworth <simonfar@fb.com> 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.
Augie Fackler - Feb. 13, 2017, 7:48 p.m.
On Mon, Feb 13, 2017 at 10:07:40AM -0800, Bryan O'Sullivan wrote:
> On Mon, Feb 13, 2017 at 9:29 AM, Simon Farnsworth <simonfar@fb.com> 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.

+1 - I only had one minor nitpick (since we're thinking about perf
anyway), I'd welcome a resend of this soon and I'll land it.

Thanks!

> _______________________________________________
> Mercurial-devel mailing list
> Mercurial-devel@mercurial-scm.org
> https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
timeless - Feb. 14, 2017, 4:51 p.m.
On Mon, Feb 13, 2017 at 12:29 PM, Simon Farnsworth <simonfar@fb.com> wrote:
> 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

> --- a/contrib/hgperf
> +++ b/contrib/hgperf
> -    begin = time.time()
> +    begin = mercurial.util.timer()
> --- 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

I think we usually split the introduction of a new feature from
switching to using the new thing.
It makes it easier to see / semi-document the new api vs. seeing the
switch to using it.
via Mercurial-devel - Feb. 16, 2017, 6:35 p.m.
On Tue, Feb 14, 2017 at 8:51 AM, timeless <timeless@gmail.com> wrote:
> On Mon, Feb 13, 2017 at 12:29 PM, Simon Farnsworth <simonfar@fb.com> wrote:
>> 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
>
>> --- a/contrib/hgperf
>> +++ b/contrib/hgperf
>> -    begin = time.time()
>> +    begin = mercurial.util.timer()
>> --- 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

As discussed on #mercurial, Augie and I find "timer" confusing,
because it sounds like it returns a timer object, but in fact it just
returns a time. Can we have a followup patch that renames it to e.g.
perftime()?

>
> I think we usually split the introduction of a new feature from
> switching to using the new thing.
> It makes it easier to see / semi-document the new api vs. seeing the
> switch to using it.
> _______________________________________________
> Mercurial-devel mailing list
> Mercurial-devel@mercurial-scm.org
> https://www.mercurial-scm.org/mailman/listinfo/mercurial-devel
Bryan O'Sullivan - Feb. 16, 2017, 6:48 p.m.
On Thu, Feb 16, 2017 at 10:35 AM, Martin von Zweigbergk via Mercurial-devel
<mercurial-devel@mercurial-scm.org> wrote:

> As discussed on #mercurial, Augie and I find "timer" confusing,
> because it sounds like it returns a timer object, but in fact it just
> returns a time. Can we have a followup patch that renames it to e.g.
> perftime()?
>

If we're gonna bikeshed, it should be called time, because that's what it
really emulates :-)
Martin von Zweigbergk - Feb. 19, 2017, 1:34 a.m.
On Feb 16, 2017 10:48 AM, "Bryan O'Sullivan" <bos@serpentine.com> wrote:


On Thu, Feb 16, 2017 at 10:35 AM, Martin von Zweigbergk via Mercurial-devel
<mercurial-devel@mercurial-scm.org> wrote:

> As discussed on #mercurial, Augie and I find "timer" confusing,
> because it sounds like it returns a timer object, but in fact it just
> returns a time. Can we have a followup patch that renames it to e.g.
> perftime()?
>

If we're gonna bikeshed, it should be called time, because that's what it
really emulates :-)


Not quite, IIUC. On recent Pythons, it calls a function that returns a
value that's useful for timing, but that's not a time since the epoch.

Patch

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__,