Python disabled logging slowing script

Question

I am using the built in Python "logging" module for my script. When I turn verbosity to "info" it seems like my "debug" messages are significantly slowing down my script.

Some of my "debug" messages print large dictionaries and I'm guessing Python is expanding the text before realizing "debug" messages are disabled. Example:

import pprint
pp = pprint.PrettyPrinter(indent=4)
logger.debug(f"Large Dict Object: {pp.pformat(obj)}")

How can I improve my performance? I'd prefer to still use Python's built in logging module. But need to figure out a "clean" way to solve this issue.

Vinay Sajip · Accepted Answer · 2022-01-18 12:30:57Z

3

There is already a feature of logging for the feature mentioned by dankal444, which is slightly neater:

if logger.isEnabledFor(logging.DEBUG):
    logger.debug(f"Large Dict Object: {pp.pformat(obj)}")

Another possible approach is to use %-formatting, which only does the formatting when actually needed (the logging event has to be processed by a handler as well as a logger to get to that point). I know f-strings are the new(ish) hotness and are performant, but it all depends on the exact circumstances as to which will offer the best result.

An example of taking advantage of lazy %-formatting:

class DeferredFormatHelper:
    def __init__(self, func, *args, *kwargs):
        self.func = func  # assumed to return a string
        self.args = args
        self.kwargs = kwargs

    def __str__(self):
        # This is called because the format string contains
        # a %s for this logging argument, lazily if and when
        # the formatting needs to happen
        return self.func(*self.args, **self.kwargs)

if logger.isEnabledFor(logging.DEBUG):
    arg = DeferredFormatHelper(pp.pformat, obj)
    logger.debug('Large Dict Object: %s', arg)

edited Jan 18, 2022 at 12:30

answered Jan 15, 2022 at 18:36

Vinay Sajip

100k15 gold badges184 silver badges196 bronze badges

Sign up to request clarification or add additional context in comments.

7 Comments

Vinay Sajip Over a year ago

It is lazier, because the %-formatting gets applied some time after the logging call, if it's needed. The f-string formatting happens before the logging call, even if the message never makes it out because of logger or handler levels or a filter blocking it.

Vinay Sajip Over a year ago

I'm talking about e.g. logger.debug('foo %i', n) - notice the subtle difference.

Kelly Bundy Over a year ago

Does that Deferred stuff make sense, guarded by that if? Seems if you get there, you will log it.

Vinay Sajip Over a year ago

It does make sense. You will make the logging call, but that doesn't necessarily mean it will get output. Have you looked at all the documentation?

Kelly Bundy Over a year ago

So it's possible that logger.debug doesn't log even though logger.isEnabledFor(logging.DEBUG) is true? The documentation makes it sound like the latter precisely means that logger.debug does log (although no, sorry, the page is long and I didn't read it all).

|

dankal444 · Accepted Answer · 2022-01-14 22:54:17Z

1

Check if the current level is good enough:

if logger.getEffectiveLevel() <= logging.DEBUG:
    logger.debug(f"Large Dict Object: {pp.pformact(obj)}")

This is not super clean but best that I can think of. You just need to encompass with this if performance bottlenecks

answered Jan 14, 2022 at 22:54

dankal444

4,2081 gold badge28 silver badges41 bronze badges

Comments

Kristoffer Ottosson · Accepted Answer · 2022-01-15 23:14:37Z

0

I can't verify where your bottleneck is, but if it's because of the pprint library, your logger will never have a chance to do anything about it. Rewriting to clarify.

from pprint import PrettyPrinter
import logging

logger = logging.getLogger()

large_object = {"very": "large container"}
pp = PrettyPrinter(indent=4)

# This is done first.
formatted_msg = pp.pformat(large_object)
# It's already formatted when it's sent to your logger.
logger.debug(f"Large dict object: {formatted_msg}")

answered Jan 15, 2022 at 23:14

Kristoffer Ottosson

1262 silver badges9 bronze badges

Collectives™ on Stack Overflow

Python disabled logging slowing script

3 Answers 3

7 Comments

Comments

Comments

Your Answer

Hot Network Questions

Collectives™ on Stack Overflow

3 Answers 3

7 Comments

Comments

Comments

Your Answer

Sign up or log in

Post as a guest

Related