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?
Lazy Logging With Lambda Expressions A potential performance improvement for applications that use logging can result from avoiding the calculation of log messages if the corresponding log level is not enabled. First, let's see a simple log statement at TRACE level:
Lazy evaluation of function parameters is useful in certain circumstances. By using lambda expressions - and hiding them behind a macro - we can achieve that in C++. However, I wouldn’t suggest actually using that like this in production code.
While invaluable, the lazy evaluation operators have significant limitations. Consider a logging function, which logs a message, and can be turned on and off at runtime based on a global value: While this works, the problem is that the building of the message string happens regardless of whether logging is enabled or not.
In reality, the logger isn’t expecting a string for the parameters. It actually accepts any object. The logger will invoke the toString method on the object to translate it into a string. The trick here is the logger will ONLY call toString if it needs to, ie if logging is enabled.
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.
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.
If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With