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 <makapuf2@gmail.com> wrote:
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 <cs@cskk.id.au>
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 15May2019 17:37, mak apuf <makapuf2@gmail.com> wrote:
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 <cs@cskk.id.au>
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
participants (3)
-
Barry Scott -
Cameron Simpson -
mak apuf