Patchwork [1,of,8,v3] mercurial: use timeit.default_timer for interval measurement

login
register
mail settings
Submitter Simon Farnsworth
Date Feb. 10, 2017, 9:06 p.m.
Message ID <bd40abfb4e5dbaf6e373.1486760775@devvm022.lla2.facebook.com>
Download mbox | patch
Permalink /patch/18407/
State Changes Requested
Headers show

Comments

Simon Farnsworth - Feb. 10, 2017, 9:06 p.m.
# HG changeset patch
# User Simon Farnsworth <simonfar@fb.com>
# Date 1486748338 28800
#      Fri Feb 10 09:38:58 2017 -0800
# Node ID bd40abfb4e5dbaf6e373636c8e7bab7a6bf34e17
# Parent  1f51b4658f21bbb797e922d155c1046eddccf91d
mercurial: use timeit.default_timer for interval measurement

In Python 2.6 and later, timeit.default_timer() provides the highest
resolution timer for profiling and performance measurement, but without a
specified epoch (on some platforms, epoch is Python start time).

Switch interval measures from time.time() to timeit.default_timer() to
exploit this.

Patch

diff --git a/contrib/hgperf b/contrib/hgperf
--- a/contrib/hgperf
+++ b/contrib/hgperf
@@ -55,17 +55,17 @@ 
 import mercurial.util
 import mercurial.dispatch
 
-import time
+import timeit
 
 def timer(func, title=None):
     results = []
-    begin = time.time()
+    begin = timeit.default_timer()
     count = 0
     while True:
         ostart = os.times()
-        cstart = time.time()
+        cstart = timeit.default_timer()
         r = func()
-        cstop = time.time()
+        cstop = timeit.default_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
@@ -24,6 +24,7 @@ 
 import random
 import sys
 import time
+import timeit
 from mercurial import (
     bdiff,
     changegroup,
@@ -190,13 +191,13 @@ 
 
 def _timer(fm, func, title=None):
     results = []
-    begin = time.time()
+    begin = timeit.default_timer()
     count = 0
     while True:
         ostart = os.times()
-        cstart = time.time()
+        cstart = timeit.default_timer()
         r = func()
-        cstop = time.time()
+        cstop = timeit.default_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,7 @@ 
 
 import array
 import struct
-import time
+import timeit
 
 from .node import (
     bin,
@@ -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 = timeit.default_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 = timeit.default_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
@@ -16,6 +16,7 @@ 
 import sys
 import tempfile
 import time
+import timeit
 
 from .i18n import _
 from .node import (
@@ -2202,7 +2203,7 @@ 
     if opts.get('force_lock') or opts.get('force_lock'):
         return 0
 
-    now = time.time()
+    now = timeit.default_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
@@ -17,6 +17,7 @@ 
 import signal
 import sys
 import time
+import timeit
 import traceback
 
 
@@ -123,7 +124,7 @@ 
         return -1
 
     msg = ' '.join(' ' in a and repr(a) or a for a in req.args)
-    starttime = time.time()
+    starttime = timeit.default_timer()
     ret = None
     try:
         ret = _runcatch(req)
@@ -135,7 +136,7 @@ 
                 raise
         ret = -1
     finally:
-        duration = time.time() - starttime
+        duration = timeit.default_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,7 @@ 
 
 import os
 import sys
-import time
+import timeit
 
 from .i18n import _
 from . import (
@@ -88,7 +88,7 @@ 
                 % (hname, funcname))
 
     ui.note(_("calling hook %s: %s\n") % (hname, funcname))
-    starttime = time.time()
+    starttime = timeit.default_timer()
 
     try:
         r = obj(ui=ui, repo=repo, hooktype=name, **args)
@@ -106,7 +106,7 @@ 
         ui.traceback()
         return True, True
     finally:
-        duration = time.time() - starttime
+        duration = timeit.default_timer() - starttime
         ui.log('pythonhook', 'pythonhook-%s: %s finished in %0.2f seconds\n',
                name, funcname, duration)
     if r:
@@ -118,7 +118,7 @@ 
 def _exthook(ui, repo, name, cmd, args, throw):
     ui.note(_("running hook %s: %s\n") % (name, cmd))
 
-    starttime = time.time()
+    starttime = timeit.default_timer()
     env = {}
 
     # make in-memory changes visible to external process
@@ -145,7 +145,7 @@ 
         cwd = pycompat.getcwd()
     r = ui.system(cmd, environ=env, cwd=cwd)
 
-    duration = time.time() - starttime
+    duration = timeit.default_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,7 @@ 
 from __future__ import absolute_import, print_function
 
 import contextlib
-import time
+import timeit
 
 from .i18n import _
 from . import (
@@ -66,7 +66,7 @@ 
     collapse_recursion = True
     thread = flamegraph.ProfileThread(fp, 1.0 / freq,
                                       filter_, collapse_recursion)
-    start_time = time.clock()
+    start_time = timeit.default_timer()
     try:
         thread.start()
         yield
@@ -74,7 +74,7 @@ 
         thread.stop()
         thread.join()
         print('Collected %d stack frames (%d unique) in %2.2f seconds.' % (
-            time.clock() - start_time, thread.num_frames(),
+            timeit.default_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,7 @@ 
 import hashlib
 import stat
 import tempfile
-import time
+import timeit
 
 from .i18n import _
 from .node import short
@@ -905,10 +905,10 @@ 
     # the operation nearly instantaneous and atomic (at least in well-behaved
     # environments).
     ui.write(_('replacing store...\n'))
-    tstart = time.time()
+    tstart = timeit.default_timer()
     util.rename(srcrepo.spath, backupvfs.join('store'))
     util.rename(dstrepo.spath, srcrepo.spath)
-    elapsed = time.time() - tstart
+    elapsed = timeit.default_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,7 @@ 
 from __future__ import absolute_import
 
 import struct
-import time
+import timeit
 
 from .i18n import _
 from . import (
@@ -297,7 +297,7 @@ 
                        (filecount, util.bytecount(bytecount)))
         handled_bytes = 0
         repo.ui.progress(_('clone'), 0, total=bytecount, unit=_('bytes'))
-        start = time.time()
+        start = timeit.default_timer()
 
         # TODO: get rid of (potential) inconsistency
         #
@@ -340,7 +340,7 @@ 
             # streamclone-ed file at next access
             repo.invalidate(clearfilecache=True)
 
-        elapsed = time.time() - start
+        elapsed = timeit.default_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,7 @@ 
 
 import array
 import errno
-import time
+import timeit
 
 from .node import (
     bin,
@@ -344,7 +344,7 @@ 
         # potentially expensive search.
         return ([], {}, valid, None, True)
 
-    starttime = time.time()
+    starttime = timeit.default_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 +359,7 @@ 
 
     fnodescache.write()
 
-    duration = time.time() - starttime
+    duration = timeit.default_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
@@ -36,6 +36,7 @@ 
 import tempfile
 import textwrap
 import time
+import timeit
 import traceback
 import zlib
 
@@ -2786,13 +2787,13 @@ 
     '''
 
     def wrapper(*args, **kwargs):
-        start = time.time()
+        start = timeit.default_timer()
         indent = 2
         _timenesting[0] += indent
         try:
             return func(*args, **kwargs)
         finally:
-            elapsed = time.time() - start
+            elapsed = timeit.default_timer() - start
             _timenesting[0] -= indent
             stderr.write('%s%s: %s\n' %
                          (' ' * _timenesting[0], func.__name__,