Merge pull request #105 from lsst/tickets/DM-32658

DM-32658: Only do getmodule if we know the log message will be issued

python/lsst/utils/timer.py

@@ -114,7 +114,7 @@ def _find_outside_stacklevel() -> int:
 
 def logPairs(obj: Any, pairs: Collection[Tuple[str, Any]], logLevel: int = logging.DEBUG,
              metadata: Optional[MutableMapping] = None,
-             logger: Optional[logging.Logger] = None) -> None:
+             logger: Optional[logging.Logger] = None, stacklevel: Optional[int] = None) -> None:
     """Log ``(name, value)`` pairs to ``obj.metadata`` and ``obj.log``
 
     Parameters
@@ -137,6 +137,12 @@ def logPairs(obj: Any, pairs: Collection[Tuple[str, Any]], logLevel: int = loggi
         Metadata object to write entries to.  Ignored if `None`.
     logger : `logging.Logger`
         Log object to write entries to.  Ignored if `None`.
+    stacklevel : `int`, optional
+        The stack level to pass to the logger to adjust which stack frame
+        is used to report the file information. If `None` the stack level
+        is computed such that it is reported as the first package outside
+        of the utils package. If a value is given here it is adjusted by
+        1 to account for this caller.
     """
     if obj is not None:
         if metadata is None:
@@ -156,13 +162,21 @@ def logPairs(obj: Any, pairs: Collection[Tuple[str, Any]], logLevel: int = loggi
         strList.append(f"{name}={value}")
     if logger is not None:
         # Want the file associated with this log message to be that
-        # of the caller.
-        stacklevel = _find_outside_stacklevel()
-        logging.getLogger("timer." + logger.name).log(logLevel, "; ".join(strList), stacklevel=stacklevel)
+        # of the caller. This is expensive so only do it if we know the
+        # message will be issued.
+        timer_logger = logging.getLogger("timer." + logger.name)
+        if timer_logger.isEnabledFor(logLevel):
+            if stacklevel is None:
+                stacklevel = _find_outside_stacklevel()
+            else:
+                # Account for the caller stack.
+                stacklevel += 1
+            timer_logger.log(logLevel, "; ".join(strList), stacklevel=stacklevel)
 
 
 def logInfo(obj: Any, prefix: str, logLevel: int = logging.DEBUG,
-            metadata: Optional[MutableMapping] = None, logger: Optional[logging.Logger] = None) -> None:
+            metadata: Optional[MutableMapping] = None, logger: Optional[logging.Logger] = None,
+            stacklevel: Optional[int] = None) -> None:
     """Log timer information to ``obj.metadata`` and ``obj.log``.
 
     Parameters
@@ -187,6 +201,12 @@ def logInfo(obj: Any, prefix: str, logLevel: int = logging.DEBUG,
         Metadata object to write entries to, overriding ``obj.metadata``.
     logger : `logging.Logger`
         Log object to write entries to, overriding ``obj.log``.
+    stacklevel : `int`, optional
+        The stack level to pass to the logger to adjust which stack frame
+        is used to report the file information. If `None` the stack level
+        is computed such that it is reported as the first package outside
+        of the utils package. If a value is given here it is adjusted by
+        1 to account for this caller.
 
     Notes
     -----
@@ -212,6 +232,10 @@ def logInfo(obj: Any, prefix: str, logLevel: int = logging.DEBUG,
         # Log messages already have timestamps.
         utcStr = datetime.datetime.utcnow().isoformat()
         _add_to_metadata(metadata, name=prefix + "Utc", value=utcStr)
+    if stacklevel is not None:
+        # Account for the caller of this routine not knowing that we
+        # are going one down in the stack.
+        stacklevel += 1
     logPairs(obj=obj,
              pairs=[
                  (prefix + "CpuTime", cpuTime),
@@ -227,7 +251,8 @@ def logInfo(obj: Any, prefix: str, logLevel: int = logging.DEBUG,
              ],
              logLevel=logLevel,
              metadata=metadata,
-             logger=logger)
+             logger=logger,
+             stacklevel=stacklevel)
 
 
 def timeMethod(_func: Optional[Any] = None, *, metadata: Optional[MutableMapping] = None,
@@ -281,16 +306,21 @@ def run(self, ...): # or any other instance method you want to time
 
     def decorator_timer(func: Callable) -> Callable:
         @functools.wraps(func)
-        def wrapper(self: Any, *args: Any, **keyArgs: Any) -> Any:
+        def timeMethod_wrapper(self: Any, *args: Any, **keyArgs: Any) -> Any:
+            # Adjust the stacklevel to account for the wrappers.
+            # stacklevel 1 would make the log message come from this function
+            # but we want it to come from the file that defined the method
+            # so need to increment by 1 to get to the caller.
+            stacklevel = 2
             logInfo(obj=self, prefix=func.__name__ + "Start", metadata=metadata, logger=logger,
-                    logLevel=logLevel)
+                    logLevel=logLevel, stacklevel=stacklevel)
             try:
                 res = func(self, *args, **keyArgs)
             finally:
                 logInfo(obj=self, prefix=func.__name__ + "End", metadata=metadata, logger=logger,
-                        logLevel=logLevel)
+                        logLevel=logLevel, stacklevel=stacklevel)
             return res
-        return wrapper
+        return timeMethod_wrapper
 
     if _func is None:
         return decorator_timer

tests/test_timer.py

@@ -16,7 +16,7 @@
 import os.path
 from dataclasses import dataclass
 
-from lsst.utils.timer import timeMethod, logPairs, time_this
+from lsst.utils.timer import timeMethod, logPairs, time_this, logInfo
 
 log = logging.getLogger("test_timer")
 
@@ -72,6 +72,36 @@ def testLogPairs(self):
         self.assertEqual(cm.records[0].filename, THIS_FILE, "log message should originate from here")
         self.assertEqual(metadata, {"name1": [0], "name2": [1]})
 
+        # Call it again with an explicit stack level.
+        # Force it to come from lsst.utils.
+        with self.assertLogs(level=logging.INFO) as cm:
+            logPairs(None, pairs, logLevel=logging.INFO, logger=logger, metadata=metadata, stacklevel=0)
+        self.assertEqual(cm.records[0].filename, "timer.py")
+
+        # Check that the log message is filtered by default.
+        with self.assertLogs(level=logging.INFO) as cm:
+            logPairs(None, pairs, logger=logger, metadata=metadata)
+            logger.info("Message")
+        self.assertEqual(len(cm.records), 1)
+
+    def testLogInfo(self):
+        metadata = {}
+        logger = logging.getLogger("testLogInfo")
+        with self.assertLogs(level=logging.INFO) as cm:
+            logInfo(None, prefix="Prefix", metadata=metadata, logger=logger, logLevel=logging.INFO)
+        self.assertEqual(cm.records[0].filename, THIS_FILE)
+        self.assertIn("PrefixUtc", metadata)
+
+        # Again with no log output.
+        logInfo(None, prefix="Prefix", metadata=metadata)
+        self.assertEqual(len(metadata["PrefixUtc"]), 2)
+
+        # With an explicit stacklevel.
+        with self.assertLogs(level=logging.INFO) as cm:
+            logInfo(None, prefix="Prefix", metadata=metadata, logger=logger, logLevel=logging.INFO,
+                    stacklevel=0)
+        self.assertEqual(cm.records[0].filename, "timer.py")
+
     def assertTimer(self, duration, task):
         # Call it twice to test the "add" functionality.
         task.sleeper(duration)