[Chicago] Taking Some Pain Out Of Python Logging

[Skip Montanaro]

> In my logger Twiggy, I have support for what I call "asynchronous
> logging" - use a child process to do the actual disk write.
> http://twiggy.wearpants.org/

More process switches.  Unless you have multiple processes feeding
into your logger (as for syslog), I suspect there's little to be
gained.  Moving loggers into separate threads or subprocesses just
increases communication and process switch overhead.  I suspect it
will be hard to improve logging performance over what the kernel does
in the way of disk buffer flushing.

That said, the stdlib logger was so slow (I think it was the special
formatters), that if you log heavily it's tempting to try and find a
better way to do things.  One thing we did was to delay string format
substitution until after the logger has decided if it needs to write
anything.  Instead of this:

    self.logger.debug("And %s's your uncle and %s's your aunt!" %
("Bob", "Mary"))

our API is

    self.logger.debug("And %s's your uncle and %s's your aunt!",
("Bob", "Mary"))

The logger does the format substitution if and only if logging is at
the debug level.  That, for us, was the slowest bit of non-disk
activity.  YMMV, of course.  If you don't log much you probably
wouldn't notice these things.  A few hundred MB per day from each of
many processes is not at all unusual for us.

Skip