Use better timing mechanisms instead of time.time()

To ensure we show accurate timing information about
lock acqusition and release times use a timing mechanism
which can not/should not move backwards.

Change-Id: I9559b20cf7de67fc474e6e17eda23791ecc4122e

3 files changed, 18 insertions, 12 deletions

diff --git a/oslo_concurrency/lockutils.py b/oslo_concurrency/lockutils.py
index db5a2be..0155dcb 100644
--- a/oslo_concurrency/lockutils.py
+++ b/oslo_concurrency/lockutils.py
@@ -22,11 +22,11 @@ import subprocess
 import sys
 import tempfile
 import threading
-import time
 import weakref
 
 import fasteners
 from oslo_config import cfg
+from oslo_utils import timeutils
 import six
 
 from oslo_concurrency._i18n import _, _LI
@@ -236,31 +236,32 @@ def synchronized(name, lock_file_prefix=None, external=False, lock_path=None,
     """
 
     def wrap(f):
+
         @six.wraps(f)
         def inner(*args, **kwargs):
-            t1 = time.time()
+            t1 = timeutils.now()
             t2 = None
             try:
                 with lock(name, lock_file_prefix, external, lock_path,
                           do_log=False, semaphores=semaphores, delay=delay):
-                    t2 = time.time()
+                    t2 = timeutils.now()
                     LOG.debug('Lock "%(name)s" acquired by "%(function)s" :: '
                               'waited %(wait_secs)0.3fs',
                               {'name': name, 'function': f.__name__,
                                'wait_secs': (t2 - t1)})
                     return f(*args, **kwargs)
             finally:
-                t3 = time.time()
+                t3 = timeutils.now()
                 if t2 is None:
                     held_secs = "N/A"
                 else:
                     held_secs = "%0.3fs" % (t3 - t2)
-
                 LOG.debug('Lock "%(name)s" released by "%(function)s" :: held '
                           '%(held_secs)s',
                           {'name': name, 'function': f.__name__,
                            'held_secs': held_secs})
         return inner
+
     return wrap
 
 
diff --git a/oslo_concurrency/processutils.py b/oslo_concurrency/processutils.py
index 13dc1f7..0fd7915 100644
--- a/oslo_concurrency/processutils.py
+++ b/oslo_concurrency/processutils.py
@@ -27,6 +27,7 @@ import time
 
 from oslo_utils import importutils
 from oslo_utils import strutils
+from oslo_utils import timeutils
 import six
 
 from oslo_concurrency._i18n import _
@@ -209,10 +210,12 @@ def execute(*cmd, **kwargs):
     cmd = [str(c) for c in cmd]
     sanitized_cmd = strutils.mask_password(' '.join(cmd))
 
+    watch = timeutils.StopWatch()
     while attempts > 0:
         attempts -= 1
+        watch.restart()
+
         try:
-            start_time = time.time()
             LOG.log(loglevel, _('Running cmd (subprocess): %s'), sanitized_cmd)
             _PIPE = subprocess.PIPE  # pylint: disable=E1101
 
@@ -240,9 +243,8 @@ def execute(*cmd, **kwargs):
 
             obj.stdin.close()  # pylint: disable=E1101
             _returncode = obj.returncode  # pylint: disable=E1101
-            end_time = time.time() - start_time
-            LOG.log(loglevel, 'CMD "%s" returned: %s in %0.3fs' %
-                    (sanitized_cmd, _returncode, end_time))
+            LOG.log(loglevel, 'CMD "%s" returned: %s in %0.3fs',
+                    sanitized_cmd, _returncode, watch.elapsed())
 
             if on_completion:
                 on_completion(obj)
diff --git a/oslo_concurrency/watchdog.py b/oslo_concurrency/watchdog.py
index 972aaa9..692e9ba 100644
--- a/oslo_concurrency/watchdog.py
+++ b/oslo_concurrency/watchdog.py
@@ -15,7 +15,8 @@
 import contextlib
 import logging
 import threading
-import time
+
+from oslo_utils import timeutils
 
 
 @contextlib.contextmanager
@@ -53,11 +54,13 @@ def watch(logger, action, level=logging.DEBUG, after=5.0):
             print "done"
 
     """
-    start = time.time()
+    watch = timeutils.StopWatch()
+    watch.start()
 
     def log():
-        msg = "%s not completed after %0.3fs" % (action, time.time() - start)
+        msg = "%s not completed after %0.3fs" % (action, watch.elapsed())
         logger.log(level, msg)
+
     timer = threading.Timer(after, log)
     timer.start()
     try: