Skip to content

Instantly share code, notes, and snippets.

Show Gist options
  • Save schnittstabil/9372911 to your computer and use it in GitHub Desktop.
Save schnittstabil/9372911 to your computer and use it in GitHub Desktop.
logging.isEnabledFor vs lazyjoin class benchmark
import logging
logging.basicConfig(level=logging.INFO)
logger = logging.getLogger("log")
def simple():
if logger.isEnabledFor(logging.DEBUG):
logger.debug(
'Stupid log message ' + ' '.join([str(i) for i in range(20)])
)
# Do something
class lazyjoin:
def __init__(self, s, items):
self.s = s
self.items = items
def __str__(self):
return self.s.join(self.items)
def lazy():
logger.debug(
'Stupid log message %s', lazyjoin(' ', (str(i) for i in range(20)))
)
# Do something
if __name__ == '__main__':
import timeit
print(min(timeit.repeat("simple()", setup="from __main__ import simple")))
print(min(timeit.repeat("lazy()", setup="from __main__ import lazy")))
@schnittstabil
Copy link
Author

my result:

$ python isEnabledFor_vs_class_benchmark.py
2.8991405550041236
13.408140633997391

@guyarad
Copy link

guyarad commented Nov 1, 2016

for the record, doing the following resulted in almost the same result for both methods. It does describe a real scenario in my case, in which the lazy logging method doesn't need any parameters and simply takes stuff from self to generate the debug message (you can see what I ended up doing here)

    import logging
    logging.basicConfig(level=logging.INFO)
    logger = logging.getLogger("log")


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


    class lazyjoin:
        def __init__(self, s, items):
            self.s = s
            self.items = items

        def __str__(self):
            return self.s.join(self.items)


    def lazy(lazy_log):
        logger.debug(
            'Stupid log message %s', lazy_log
        )
        # Do something

    if __name__ == '__main__':
        import timeit
        print(min(timeit.repeat("simple()", setup="from __main__ import simple")))
        print(min(timeit.repeat("lazy(lazy_log)", setup="from __main__ import lazy, lazyjoin; lazy_log = lazyjoin(' ', (str(i) for i in range(20)))")))

EDIT: syntax highligting added by @schnittstabil

@schnittstabil
Copy link
Author

schnittstabil commented Nov 1, 2016

@guyarad You're ignoring the time needed to create the lazyjoin instance lazy_log:

setup="… lazy_log = lazyjoin(' ', (str(i) for i in range(20)))"

For a real world scenario you have to measure that time too.

At the time of writing my stackoverflow answer, logger.isEnabledFor(logging.DEBUG) was 4 times faster than creating a lazyjoin instance.
See also my stackoverflow answer to Python: how to do lazy debug logging.


Nevertheless, even in your scenario, I see no need to create those expensive LazyLogging instances.
Instead you could use a simple and efficient lazy_debug function:

def lazy_debug(logger, msg, fn):
    if logger.isEnabledFor(logging.DEBUG):
        logger.debug(msg, fn())

class MyClass(object):
    def __init__(self):
        pass

    def _debug_1(self):
        return "my debugging string 1"

    def _debug_2(self):
        return "my debugging string 2"

    def _debug_3(self):
        return "my debugging string 3"

    def m_1(self):
        lazy_debug(logger, "Info: %s", self._debug_1)

    def m_2(self):
        lazy_debug(logger, "Info: %s", self._debug_2)

    def m_3(self):
        lazy_debug(logger, "Info: %s", self._debug_3)

If you want to improve this, you may extend the logger class with a lazy_debug method, which is hard though, IIRC.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment