Merge "Add useful 'time_it' decorator"

oslo_utils/tests/test_timeutils.py

@@ -15,6 +15,7 @@
 
 import calendar
 import datetime
+import logging
 import time
 
 import iso8601
@@ -384,6 +385,99 @@ class TestIso8601Time(test_base.BaseTestCase):
         self.assertTrue(naive < dt)
 
 
+class TimeItTest(test_base.BaseTestCase):
+
+    @mock.patch('time.sleep')
+    @mock.patch('oslo_utils.timeutils.now')
+    def test_timed(self, mock_now, mock_sleep):
+        mock_now.side_effect = monotonic_iter(incr=0.1)
+        fake_logger = mock.MagicMock(logging.getLogger(), autospec=True)
+
+        @timeutils.time_it(fake_logger)
+        def slow_function():
+            time.sleep(0.1)
+
+        slow_function()
+        self.assertTrue(mock_now.called)
+        self.assertTrue(mock_sleep.called)
+        self.assertTrue(fake_logger.log.called)
+        fake_logger.log.assert_called_with(logging.DEBUG, mock.ANY, mock.ANY)
+
+    @mock.patch('time.sleep')
+    @mock.patch('oslo_utils.timeutils.now')
+    def test_no_timed_disabled(self, mock_now, mock_sleep):
+        mock_now.side_effect = monotonic_iter(incr=0.1)
+        fake_logger = mock.MagicMock(logging.getLogger(), autospec=True)
+
+        @timeutils.time_it(fake_logger, enabled=False)
+        def slow_function():
+            time.sleep(0.1)
+
+        slow_function()
+        self.assertFalse(mock_now.called)
+        self.assertFalse(fake_logger.log.called)
+
+    @mock.patch('time.sleep')
+    @mock.patch('oslo_utils.timeutils.now')
+    def test_no_timed_to_fast(self, mock_now, mock_sleep):
+        mock_now.side_effect = monotonic_iter(incr=0.1)
+        fake_logger = mock.MagicMock(logging.getLogger(), autospec=True)
+
+        @timeutils.time_it(fake_logger, min_duration=10)
+        def fast_function():
+            pass
+
+        fast_function()
+        self.assertFalse(fake_logger.log.called)
+
+    @mock.patch('time.sleep')
+    @mock.patch('oslo_utils.timeutils.now')
+    def test_no_timed_exception(self, mock_now, mock_sleep):
+        mock_now.side_effect = monotonic_iter(incr=0.1)
+        fake_logger = mock.MagicMock(logging.getLogger(), autospec=True)
+
+        @timeutils.time_it(fake_logger)
+        def broken_function():
+            raise IOError("Broken")
+
+        self.assertRaises(IOError, broken_function)
+        self.assertFalse(fake_logger.log.called)
+
+    @mock.patch('time.sleep')
+    @mock.patch('oslo_utils.timeutils.now')
+    def test_timed_custom_message(self, mock_now, mock_sleep):
+        mock_now.side_effect = monotonic_iter(incr=0.1)
+        fake_logger = mock.MagicMock(logging.getLogger(), autospec=True)
+
+        @timeutils.time_it(fake_logger, message="That took a long time")
+        def slow_function():
+            time.sleep(0.1)
+
+        slow_function()
+        self.assertTrue(mock_now.called)
+        self.assertTrue(mock_sleep.called)
+        self.assertTrue(fake_logger.log.called)
+        fake_logger.log.assert_called_with(logging.DEBUG,
+                                           "That took a long time",
+                                           mock.ANY)
+
+    @mock.patch('time.sleep')
+    @mock.patch('oslo_utils.timeutils.now')
+    def test_timed_custom_level(self, mock_now, mock_sleep):
+        mock_now.side_effect = monotonic_iter(incr=0.1)
+        fake_logger = mock.MagicMock(logging.getLogger(), autospec=True)
+
+        @timeutils.time_it(fake_logger, log_level=logging.INFO)
+        def slow_function():
+            time.sleep(0.1)
+
+        slow_function()
+        self.assertTrue(mock_now.called)
+        self.assertTrue(mock_sleep.called)
+        self.assertTrue(fake_logger.log.called)
+        fake_logger.log.assert_called_with(logging.INFO, mock.ANY, mock.ANY)
+
+
 class StopWatchTest(test_base.BaseTestCase):
     def test_leftover_no_duration(self):
         watch = timeutils.StopWatch()

oslo_utils/timeutils.py

@@ -19,6 +19,7 @@ Time related utilities and helper functions.
 
 import calendar
 import datetime
+import logging
 import time
 
 from debtcollector import removals
@@ -357,6 +358,53 @@ class Split(object):
         return r
 
 
+def time_it(logger, log_level=logging.DEBUG,
+            message="It took %(seconds).02f seconds to"
+                    " run function '%(func_name)s'",
+            enabled=True, min_duration=0.01):
+    """Decorator that will log how long its decorated function takes to run.
+
+    This does **not** output a log if the decorated function fails
+    with an exception.
+
+    :param logger: logger instance to use when logging elapsed time
+    :param log_level: logger logging level to use when logging elapsed time
+    :param message: customized message to use when logging elapsed time,
+                    the message may use automatically provide values
+                    ``%(seconds)`` and ``%(func_name)`` if it finds those
+                    values useful to record
+    :param enabled: whether to enable or disable this decorator (useful to
+                    decorate a function with this decorator, and then easily
+                    be able to switch that decoration off by some config or
+                    other value)
+    :param min_duration: argument that determines if logging is triggered
+                         or not, it is by default set to 0.01 seconds to avoid
+                         logging when durations and/or elapsed function call
+                         times are less than 0.01 seconds, to disable
+                         any ``min_duration`` checks this value should be set
+                         to less than or equal to zero or set to none
+    """
+
+    def decorator(func):
+        if not enabled:
+            return func
+
+        @six.wraps(func)
+        def wrapper(*args, **kwargs):
+            with StopWatch() as w:
+                result = func(*args, **kwargs)
+            time_taken = w.elapsed()
+            if min_duration is None or time_taken >= min_duration:
+                logger.log(log_level, message,
+                           {'seconds': time_taken,
+                            'func_name': reflection.get_callable_name(func)})
+            return result
+
+        return wrapper
+
+    return decorator
+
+
 class StopWatch(object):
     """A simple timer/stopwatch helper class.