easier lazy logging in stdlib ?
Hello all, Let's consider logging.debug(expensive_function()) There are a few possibilities to run an expensive function when logging only if the log is effectively output : - eager formatting + calling by using fstrings or .format(expensive_func()) - formatting being done lazily by separating the log string from the arguments (by using % syntax which is dated maybe) - creating a Lazy object that calls expensive_func when calling its __str__ method, but that it a bit cumbersome because you have to provide a lazy class for each, that only work for string values and the cost of creating Lazy is eager. - checking logging.isEnabledFor(lvl) explicitely (but then the level is displayed twice, in enabled_for and in logging.LEVEL) Maybe we can integrate a form of lazy evaluation for simple logging. Different options are : a- just evaluate when an argument is callable (not bw compatible, what if this is unexpected and has side effects) b- provide a LazyFormatter that does the preceding for any "%s" or "%d" arg when used c- provide a callable as part of the logging arguments and provide a "%*s or %*d" format string instead of %s and %d (by example) for calling the function before embedding it d- check if a parameter has a special method such as __lazy__ at render time e- provide a Lazy class in logging module to wrap lazy logging idiom: class Lazy : def __init__(self, callable, *args, **kwargs) : self.callable = callable self.args=args self.kwargs=kwargs def __lazy__(self) : return self.callable(*args, **kwargs) and checking if an argument is of Lazy type (again the drawback is that this eagerly instanciate this class) I'd prefer b,c or d+e any thoughts? -- makapuf
On 15May2019 17:37, mak apuf
Let's consider logging.debug(expensive_function())
There are a few possibilities to run an expensive function when logging only if the log is effectively output :
- eager formatting + calling by using fstrings or .format(expensive_func()) - formatting being done lazily by separating the log string from the arguments (by using % syntax which is dated maybe) - creating a Lazy object that calls expensive_func when calling its __str__ method, but that it a bit cumbersome because you have to provide a lazy class for each, that only work for string values and the cost of creating Lazy is eager. - checking logging.isEnabledFor(lvl) explicitely (but then the level is displayed twice, in enabled_for and in logging.LEVEL)
I think c is the most viable solution. The "only works for string
values" isn't such a big deal: logging writes strings, so string output
is the end game anyway.
Then you can go:
logging.debug("Wow: This: %s", Lazy(expensive_function, args...))
However, there's still a problem: the logging documentation suggests
that the message is assembled before decenting the log tree to dispatch
it, which means that Lazy.__str__ gets called even when debug level
logging is not happening.
The logging infrastructure would need to make an intenral change so that
the message composition (the implicit % formatting of the args) only
happens if it is needed, maybe where the handler.emit method gets
called.
With taht, I think your Lazy class simply using __str__ instead of
__lazy__ might be all you need, and it wouldn't need to be part of the
logging module: roll your own.
The other solutions seem to either:
A: Require some kind of change to Python to support deferring function
calls so that some simple variation on:
logging.debug(expensive_function())
somehow does not call expensive_function, or a different form of
.debug() (and friends) where expensive_function was some kind of
callback to be triggered at need, which is where you already are with
the .emit issue above.
B: Require careful polling of the logging status, which is intrusive.
As I understand it, logging.debug() just submits a message with "debug"
level, and the logging tree decides where it gets used. In a sense
you're back to the Lazy.__str__ approach if the enabled stuff
(isEnabledFor, getEffectiveLevel) don't suffice.
Disclaimer: my logging fu is a bit weak; I've got a wrapper module for
it largely to avoid thinking about it, just providing a simple call
layer to the root logger :-)
Cheers,
Cameron Simpson
This came up 2 years ago. You might want to read this article on LWN that covered the discussion. https://lwn.net/Articles/716986/ https://lwn.net/Articles/716986/ Assuming that the log code you call will spot a callable and call it you can do this: log_function( lambda : expensive_function() ) Otherwise you end up needed to do: if log_obj.is_enabled(): log_obj.log_function( expensive_function() ) If log is an object that provides __bool__ and __call__ you could write: if log_obj: log_obj( expensive_function() ) or log_obj and log_obj( expensive_functon() ) For example: class Log: def __init__( self ): self.enabled = True def __bool__( self ): return self.enabled def __call__( self, msg ): print( 'Log: %s' % (msg,) ) log = Log() print( 'Log when enabled' ) if log: log( 'log is enabled' ) log and log( 'log is enabled' ) log.enabled = False print( 'Log when disabled' ) if log: log( 'log is enabled' ) log and log( 'log is enabled' ) print( 'Done' ) Which produces: $ python3 log.py Log when enabled Log: log is enabled Log: log is enabled Log when disabled Done Barry
On 15 May 2019, at 16:37, mak apuf
wrote: Hello all,
Let's consider logging.debug(expensive_function())
There are a few possibilities to run an expensive function when logging only if the log is effectively output :
- eager formatting + calling by using fstrings or .format(expensive_func()) - formatting being done lazily by separating the log string from the arguments (by using % syntax which is dated maybe) - creating a Lazy object that calls expensive_func when calling its __str__ method, but that it a bit cumbersome because you have to provide a lazy class for each, that only work for string values and the cost of creating Lazy is eager. - checking logging.isEnabledFor(lvl) explicitely (but then the level is displayed twice, in enabled_for and in logging.LEVEL)
Maybe we can integrate a form of lazy evaluation for simple logging. Different options are : a- just evaluate when an argument is callable (not bw compatible, what if this is unexpected and has side effects) b- provide a LazyFormatter that does the preceding for any "%s" or "%d" arg when used c- provide a callable as part of the logging arguments and provide a "%*s or %*d" format string instead of %s and %d (by example) for calling the function before embedding it d- check if a parameter has a special method such as __lazy__ at render time e- provide a Lazy class in logging module to wrap lazy logging idiom:
class Lazy : def __init__(self, callable, *args, **kwargs) : self.callable = callable self.args=args self.kwargs=kwargs
def __lazy__(self) : return self.callable(*args, **kwargs)
and checking if an argument is of Lazy type (again the drawback is that this eagerly instanciate this class)
I'd prefer b,c or d+e
any thoughts?
-- makapuf _______________________________________________ Python-ideas mailing list Python-ideas@python.org https://mail.python.org/mailman/listinfo/python-ideas Code of Conduct: http://python.org/psf/codeofconduct/
participants (3)
-
Barry Scott
-
Cameron Simpson
-
mak apuf