From 346c27b7351ced4444fb29bdc95474926da39821 Mon Sep 17 00:00:00 2001 From: Joshua Harlow Date: Mon, 5 Oct 2015 15:53:37 -0700 Subject: [PATCH] Add useful 'time_it' decorator Create a helpful decorator that can be attached to functions or methods to show how long they take to run; internally it uses a stop watch and provided logger to log with (and an optional logging level to use). An example: >>> from oslo_utils import timeutils >>> import logging >>> import time >>> logging.basicConfig(level=logging.DEBUG) >>> logger = logging.getLogger() >>> >>> @timeutils.time_it(logger) ... def a(): ... time.sleep(0.2) ... >>> a() DEBUG:root:It took 0.20 seconds to run function '__main__.a' Change-Id: Ia41d5b6910f7ebe2dd93aaf6ca1defe158f8310c --- oslo_utils/tests/test_timeutils.py | 94 ++++++++++++++++++++++++++++++ oslo_utils/timeutils.py | 48 +++++++++++++++ 2 files changed, 142 insertions(+) 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 2420428a..1c41abea 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 @@ -322,6 +323,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.