Python - Does Logging Using .format Creates Extra Cpu Cycles

test.py import logging # V1 logging.debug('%s before you %s', 'Look', 'leap!') # V2 logging.debug('{} before you {}'.format('Look', 'leap!')) I have the following code above. Is

Solution 1:

Yes, it has to do extra work when you do it this way, creating strings that will never be used. That said, a small hack will allow you to switch to lazily formatted messages.

The Python folks provide a how to guide for switching though, either by using a wrapper class with a __str__ that is only invoked if the logging actually occurs, or by using a LoggerAdapter subclass wrapper for a logger that performs the necessary brace formatting lazily (so at time of use there is no extra kruft at all). The latter approach is the cleanest at time of use. The simple example from the how to guide is the following:

import logging

classMessage(object):
    def__init__(self, fmt, args):
        self.fmt = fmt
        self.args = args

    def__str__(self):
        return self.fmt.format(*self.args)

classStyleAdapter(logging.LoggerAdapter):
    def__init__(self, logger, extra=None):
        super(StyleAdapter, self).__init__(logger, extra or {})

    deflog(self, level, msg, *args, **kwargs):
        if self.isEnabledFor(level):
            msg, kwargs = self.process(msg, kwargs)
            self.logger._log(level, Message(msg, args), (), **kwargs)

logger = StyleAdapter(logging.getLogger(__name__))

defmain():
    logger.debug('Hello, {}', 'world!')

if __name__ == '__main__':
    logging.basicConfig(level=logging.DEBUG)
    main()

In actual code, Message and StyleAdapter would likely be hidden in a separate module, leaving very little custom code in modules that use them.

Solution 2:

Seriously, you're worrying about the wrong problem. Yes, the string will be formatted and maybe ultimately discarded. No, it doesn't matter.

How do I know?

• Have you measured it? I bet you haven't and if you did you'd find the time to format the string is tiny, orders of magnitudes less than the time to write to the disk, and close to the time it takes to call the function.

• If the logging is in a tight loop, called thousands of times, your log will be ugly and hard to use. So I bet it's not there, or won't be when you're done debugging.

• If the logging isn't in a tight loop, the total formatting time for lost messages will be miniscule.

• If the program is CPU-intensive, and spends much time in the Python interpreter, logging isn't why. You'll need to look for Python techniques/libraries that relieve the interpreter of work, or a language that does.

• If misuse of the log module were a significant concern to many programmers, there would be warnings in the documentation or fixes in the code. You have too much company to have independently discovered a trivial optimization problem.

• I have seen C programs that use heavy-duty debugging logs, in which printf contributes significant overhead. But that's because the rest of C is so lean. If C had garbage collection, dynamic name resolution, and list comprehension, etc., formatted I/O would start to look cheap.

The most efficient way to use the log module is the way that's easiest for you to program, because your time (I hope!) isn't cheap. If someone complains about your "wasted cycles", ask him to show how it accounts for even 1% of the running time of your program. Then you can return your focus to something that matters.