Lazy Log Line Evaluation

Question

I am using the standard python registration 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 problem is that although the debugging level is not enabled, this stupid log message is evaluated at each iteration of the loop, which affects performance poorly.

Is there any solution for this?

In C ++, we have the log4cxx package that provides macros such as:
LOG4CXX_DEBUG(logger, messasage)
It effectively evaluates

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

But since there are no macros in Python (AFAIK) if there is an efficient way of logging?

Answer 1

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

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

... instead of this:

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

The logging module is smart enough not to display the full log message unless the message is actually logged somewhere.

To apply this function to your specific query, you can 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 the generator expression, adding to laziness):

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

Here is a demo that shows that 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 call to Logger.info () got into an assertion error, while logger.debug () was not that far.

Answer 2

Of course, the following is not as effective as a macro:

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

but simple, evaluated in a lazy way and 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))) ) 

For my installation see benchmark-src .

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 will notice that the first logger.debug command logger.debug not take 20 seconds. This indicates that the argument is not evaluated when the logging level is below the set level.

Answer 4

As Shane points out, using

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

... instead of this:

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

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

This does not completely solve the problem, however, since you may have to preprocess the values ​​for formatting in a string, for example:

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

In this case, obj.get_a() and obj.get_b() will be computed even if no protocols occur.

The solution to this is to use lambda functions, but this requires several additional mechanisms:

 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 in with the following:

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

In this case, the lambda function will be called only if log.debug decides to perform formatting, so it calls the __str__ method.

Keep in mind: the overhead of this solution can greatly exceed the benefit :-) But, at least theoretically, this allows you to make complete lazy notes.

Answer 5

I imagine 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) 

Using:

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

Source example:

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

As you can see, this also covers another answer that uses a lambda function, but uses more memory with an attribute value and extension. However, this saves more memory: Using __slots__?

Finally, by far the most effective solution is still the following option:

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

Answer 6

If you depend only on accessing global state attributes, you can create an instance of the python class and lazify it 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 ) 

Connected:

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