diff --git a/oslo_utils/tests/test_timeutils.py b/oslo_utils/tests/test_timeutils.py index ea0b5c1c..0f7f7aba 100644 --- a/oslo_utils/tests/test_timeutils.py +++ b/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() diff --git a/oslo_utils/timeutils.py b/oslo_utils/timeutils.py index 3612c40a..52e99b1d 100644 --- a/oslo_utils/timeutils.py +++ b/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.