Lazy logger message string evaluation

Question

I'm using standard python logging module in my python application:

import logging
logging.basicConfig(level=logging.INFO)
logger = logging.getLogger("log")
while True:
  logger.debug('Stupid log message " + ' '.join([str(i) for i in range(20)]) )
  # Do something

The issue is that although debug level is not enable, that stupid log message is evaluated on each loop iteration, which harms performance badly.

Is there any solution for this?

In C++ we have log4cxx package that provides macros like this:
LOG4CXX_DEBUG(logger, messasage)
That effectively evaluates to

if (log4cxx::debugEnabled(logger)) {
    log4cxx.log(logger,log4cxx::LOG4CXX_DEBUG, message)
}

But since there are no macros in Python (AFAIK), if there a efficient way to do logging?

Republic

Answer 1

The logging module already has partial support for what you want to do. Do this:

log.debug("Some message: a=%s b=%s", a, b)

... instead of this:

log.debug("Some message: a=%s b=%s" % (a, b))

The logging module is smart enough to not produce the complete log message unless the message actually gets logged somewhere.

To apply this feature to your specific request, you could create a lazyjoin class.

class lazyjoin:
    def __init__(self, s, items):
        self.s = s
        self.items = items
    def __str__(self):
        return self.s.join(self.items)

Use it like this (note the use of a generator expression, adding to the laziness):

logger.info('Stupid log message %s', lazyjoin(' ', (str(i) for i in range(20))))

Here is a demo that shows this works.

>>> import logging
>>> logging.basicConfig(level=logging.INFO)
>>> logger = logging.getLogger("log")
>>> class DoNotStr:
...     def __str__(self):
...         raise AssertionError("the code should not have called this")
... 
>>> logger.info('Message %s', DoNotStr())
Traceback (most recent call last):
...
AssertionError: the code should not have called this
>>> logger.debug('Message %s', DoNotStr())
>>>

In the demo, The logger.info() call hit the assertion error, while logger.debug() did not get that far.

Bello

wow, so interesting! What about python >= 3.5 f-strings? There it doesn't doe it lazy (I tested it) – Leptorrhine

For f-strings, see https://mcmap.net/q/95234/-how-to-postpone-defer-the-evaluation-of-f-strings which should also be applicable here. – Gothicism

Answer 2

Of course the following is not as efficient as a Macro:

if logger.isEnabledFor(logging.DEBUG):
    logger.debug(
        'Stupid log message ' + ' '.join([str(i) for i in range(20)])
    )

but simple, evaluates in lazy fashion and is 4 times faster than the accepted answer:

class lazyjoin:
    def __init__(self, s, items):
        self.s = s
        self.items = items

    def __str__(self):
        return self.s.join(self.items)

logger.debug(
    'Stupid log message %s', lazyjoin(' ', (str(i) for i in range(20)))
)

See benchmark-src for my setup.

Hostetler

Simple and efficient. I like that. This should earn more upvotes. – Fluorosis

The efficiency depends on the case at hand and you should always benchmark your own scenario. In my case, the lazy logging didn't require any arguments, but could collect stuff from the class upon invoke the __str__. So essentially, I got almost the same result. See my comment here – Ergo

@guyarad: You have take the time needed to create lazyjoin instances into account too. See also my answer to Python: how to do lazy debug logging. – Hostetler

@Hostetler not necessarily. you can check my full description. In my case, I didn't need arguments, just a method call. So I could create the lazy object once, and pass the object itself (without creating it). It made things just slightly worse that then "if" suggestion. You can check my gist I based of your gist. – Ergo

Answer 3

import logging
import time

logging.basicConfig(level=logging.INFO)
logger = logging.getLogger("log")

class Lazy(object):
    def __init__(self,func):
        self.func=func
    def __str__(self):
        return self.func()

logger.debug(Lazy(lambda: time.sleep(20)))

logger.info(Lazy(lambda: "Stupid log message " + ' '.join([str(i) for i in range(20)])))
# INFO:log:Stupid log message 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19

If you run the script, you'll notice the first logger.debug command does not take 20 seconds to execute. This shows the argument is not evaluated when the logging level is below the set level.

Proudman

This is because you are using lambdas! See @Pierre-Antoine answer. – Hardening

Answer 4

As Shane points out, using

log.debug("Some message: a=%s b=%s", a, b)

... instead of this:

log.debug("Some message: a=%s b=%s" % (a, b))

saves some time by only performing the string formatting if the message is actually logged.

This does not completely solve the problem, though, as you may have to pre-process the values to format into the string, such as:

log.debug("Some message: a=%s b=%s", foo.get_a(), foo.get_b())

In that case, obj.get_a() and obj.get_b() will be computed even if no logging happens.

A solution to that would be to use lambda functions, but this requires some extra machinery:

class lazy_log_debug(object):
    def __init__(self, func):
        self.func = func
        logging.debug("%s", self)
    def __str__(self):
        return self.func()

... then you can log with the following:

lazy_log_debug(lambda: "Some message: a=%s b=%s" % (foo.get_a(), foo.get_b()))

In that case, the lambda function will only be called if log.debug decides to perform the formatting, hence calling the __str__ method.

Mind you: the overhead of that solution may very well exceed the benefit :-) But at least in theory, it makes it possible to do perfectly lazy logging.

Platitudinous

Answer 5

I present, Lazyfy:

class Lazyfy(object):
    __slots__ = 'action', 'value'

    def __init__(self, action, *value):
        self.action = action
        self.value = value

    def __str__(self):
        return self.action(*self.value)

Usage:

from pprint import pformat
log.debug("big_result: %s", Lazyfy(pformat, big_result))
log.debug( "x y z: %s", Lazyfy( lambda x, y, z: ' ,'.join( [x, y, z] ), '1', '2', '3' ) )

The original example:

logger.info('Stupid log message %s', Lazyfy(lambda: ' '.join((str(i) for i in range(20)))))

As you see, this also covers the other answer which uses lambda function, but uses more memory with the value atribute and expansion. However, it saves more memory with: Usage of __slots__?

Finally, by far, the most efficient solution still being the following as suggested another answer:

if logger.isEnabledFor(logging.DEBUG): 
    logger.debug('Stupid log message ' + ' '.join([str(i) for i in range(20)]))

Lofty

Answer 6

If you depend only on accessing global state attributes, you can instantiate a python class and lazify it by using the __str__ method:

class get_lazy_debug(object):
    def __repr__(self):
        return ' '.join(
                str(i) for i in range(20)
            )

# Allows to pass get_lazy_debug as a function parameter without 
# evaluating/creating its string!
get_lazy_debug = get_lazy_debug()

logger.debug( 'Stupid log message', get_lazy_debug )

Related:

1. Conditionally evaluated debug statements in Python
2. What are metaclasses in Python?

Lofty