util: log: Added log_time decorator

Fixes: #1088

CHANGELOG.md

@@ -9,6 +9,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 - Consolidate test case classes
 - Tutorial on how to load models dynamically
   https://intel.github.io/dffml/tutorials/models/load.html
+- `log_time` decorator for logging running time of functions/coroutines.
 - Download progressbar in `util/net.py`
 - Usecase example notebook for "Moving between models"
 - Documentation and testing support for notebooks

dffml/util/log.py

@@ -1,7 +1,11 @@
 # SPDX-License-Identifier: MIT
 # Copyright (c) 2019 Intel Corporation
 """Logging"""
+import time
 import logging
+import inspect
+import functools
+from contextlib import contextmanager
 
 LOGGER = logging.getLogger(__package__)
 
@@ -28,3 +32,72 @@ def get_download_logger(root_logger):
     duplicate_filter = DuplicateFilter()
     logger.addFilter(duplicate_filter)
     return logger
+
+
+def log_time(func):
+    """
+    Decorator that can take either coroutine or normal function
+    and log its runtime.
+
+    Examples
+    --------
+
+    >>> import time
+    >>> import asyncio
+    >>> import logging
+    >>>
+    >>> logging.basicConfig(level=logging.DEBUG)
+    >>>
+    >>> from dffml import log_time
+    >>>
+    >>> @log_time
+    ... def simple_function():
+    ...     time.sleep(1)
+    ...     return True
+    ...
+    >>>
+    >>> @log_time
+    ... async def coroutine():
+    ...     time.sleep(1)
+    ...     return True
+    ...
+    >>>
+    >>> simple_function()
+    True
+    >>>
+    >>> asyncio.run(coroutine())
+    True
+
+    You should see
+
+    .. code-block::
+
+        DEBUG:dffml.util.duration_logger: coroutine took 1.0 seconds
+
+    Since logging was enabled using ``basicConfig``.
+    """
+
+    logger = LOGGER.getChild("duration_logger")
+
+    @contextmanager
+    def time_it():
+        start_ts = time.monotonic()
+        yield
+        dur = time.monotonic() - start_ts
+        logger.debug(" {} took {:.2} seconds".format(func.__name__, dur))
+
+    @functools.wraps(func)
+    def wrapper(*args, **kwargs):
+        if inspect.iscoroutinefunction(func):
+
+            async def tmp():
+                with time_it():
+                    return await func(*args, **kwargs)
+
+            return tmp()
+
+        else:
+            with time_it():
+                return func(*args, **kwargs)
+
+    return wrapper

tests/util/test_log.py

@@ -0,0 +1,42 @@
+import re
+import time
+
+from dffml.util.log import log_time
+from dffml.util.asynctestcase import AsyncTestCase
+
+
+class TestTimeLog(AsyncTestCase):
+    def test_function(self):
+        @log_time
+        def dummy_function():
+            time.sleep(0.1)
+            return True
+
+        with self.assertLogs(level="DEBUG") as captured_logs:
+            dummy_function()
+
+        self.assertEqual(len(captured_logs.records), 1)
+        self.assertTrue(
+            re.match(
+                " dummy_function took [0-9]*.[0-9]+ seconds",
+                captured_logs.records[0].getMessage(),
+            )
+        )
+
+    async def test_coroutine(self):
+        @log_time
+        async def dummy_coroutine():
+            time.sleep(0.1)
+            return True
+
+        with self.assertLogs(level="DEBUG") as captured_logs:
+            await dummy_coroutine()
+
+        self.assertEqual(len(captured_logs.records), 1)
+
+        self.assertTrue(
+            re.match(
+                " dummy_coroutine took [0-9]*.[0-9]+ seconds",
+                captured_logs.records[0].getMessage(),
+            )
+        )