Python logger.debug converting arguments to string without logging

Question

I'm optimizing a Python program that performs some sort of calculation. It uses NumPy quite extensively. The code is sprinkled with logger.debug calls (logger is the standard Python log object).

When I run cProfile I see that Numpy's function that converts an array to string takes 50% of the execution time. This is surprising, since there is no handler that outputs messages as the DEBUG level, only INFO and above.

Why is the logger converting its arguments to string even though nobody is going to use this string? Is there a way to prevent it (other than not performing the logger calls)?

Answer 1

Without seeing your code, it's hard to tell what's happening, but looking at the source code for logging.__init__.py for both Python2.7 and Python3.4 (what I had lying around) shows that a call to logger.debug(...) for example, looks like:

if self.isEnabledFor(DEBUG):
    self._log(DEBUG, msg, args, **kwargs)

Which implies that if DEBUG isn't enabled, the logger isn't going to do any processing on any of the arguments.

One quick note, that I've burned myself on before though, is that you may be accidentally building the string before ever calling logging.debug(...). Note the difference:

logger.debug("My big array: %s" % myBigArray) ## DON'T DO THIS
logger.debug("My big array: %s", myBigArray)  ## much better

The difference is the first line does the string-formatting before it ever even gets into logger.debug - you're passing in a single argument, which is a (potentially large) string. The second line, on the other hand, will do the string-formatting only if DEBUG is enabled.