Оценка строки сообщения ленивого регистратора

Question

Я использую стандартный модуль регистрации Python в своем приложении Python:

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

Проблема в том, что хотя уровень отладки не включен, это глупое сообщение журнала оценивается на каждой итерации цикла, что сильно снижает производительность.

Есть ли какое-то решение для этого?

В C ++ у нас есть пакет log4cxx, который предоставляет такие макросы:
LOG4CXX_DEBUG(logger, messasage)
Это эффективно оценивает

if (log4cxx::debugEnabled(logger)) {
    log4cxx.log(logger,log4cxx::LOG4CXX_DEBUG, message)
}

Но поскольку в Python нет макросов (AFAIK), существует ли эффективный способ ведения журнала?

Answer 1

Модуль регистрации уже частично поддерживает то, что вы хотите сделать. Сделайте это:

log.debug("Some message: a=%s b=%s", a, b)

... вместо этого:

log.debug("Some message: a=%s b=%s" % (a, b))

Модуль ведения журнала достаточно умен, чтобы не создавать полное сообщение журнала, если только сообщение фактически не записано в журнал.

Чтобы применить эту функцию к вашему конкретному запросу, вы можете создать класс lazyjoin.

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

Используйте это так (обратите внимание на использование выражения генератора, добавляя к лени):

logger.info('Stupid log message %s', lazyjoin(' ', (str(i) for i in range(20))))

Вот демонстрация, которая показывает это работает.

>>> 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())
>>>

В демонстрационной версии вызов logger.info () попал в ошибку подтверждения, в то время как logger.debug () не зашел так далеко.

Answer 2

Конечно, следующее не так эффективно, как макрос:

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

но просто, оценивает лениво и в 4 раза быстрее принятого ответа :

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)))
)

См. benchmark-src для моей настройки.

Answer 3

import logging
import time

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

class Lazy(object):
    def __init__(self,func):
        self.func=func
    def __str__(self):
        return self.func()

logger.debug(Lazy(lambda: time.sleep(20)))

logger.info(Lazy(lambda: "Stupid log message " + ' '.join([str(i) for i in range(20)])))
# INFO:log:Stupid log message 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19

Если вы запустите скрипт, вы заметите, что выполнение первой команды logger.debug не займет 20 секунд. Это показывает, что аргумент не оценивается, когда уровень ведения журнала ниже заданного уровня.

Answer 4

Как указывает Шейн, используя

log.debug("Some message: a=%s b=%s", a, b)

... вместо этого:

log.debug("Some message: a=%s b=%s" % (a, b))

экономит время, выполняя форматирование строки, только если сообщение действительно зарегистрировано.

Однако это не решает проблему полностью, поскольку вам, возможно, придется предварительно обработать значения для форматирования в строку, например:

log.debug("Some message: a=%s b=%s", foo.get_a(), foo.get_b())

В этом случае obj.get_a() и obj.get_b() будут вычислены даже , если не ведется регистрация.

Решением этой проблемы было бы использование лямбда-функций, но для этого требуется дополнительный механизм:

class lazy_log_debug(object):
    def __init__(self, func):
        self.func = func
        logging.debug("%s", self)
    def __str__(self):
        return self.func()

... тогда вы можете войти со следующим:

lazy_log_debug(lambda: "Some message: a=%s b=%s" % (foo.get_a(), foo.get_b()))

В этом случае лямбда-функция будет только вызываться, если log.debug решит выполнить форматирование, следовательно, вызовет метод __str__.

Имейте в виду: издержки этого решения могут значительно превысить выгоду :-) Но, по крайней мере, теоретически, это позволяет вести ленивую регистрацию.

Answer 5

Я представляю, Lazyfy:

class Lazyfy(object):
    __slots__ = 'action', 'value'

    def __init__(self, action, *value):
        self.action = action
        self.value = value

    def __str__(self):
        return self.action(*self.value)

Использование:

from pprint import pformat
log.debug("big_result: %s", Lazyfy(pformat, big_result))
log.debug( "x y z: %s", Lazyfy( lambda x, y, z: ' ,'.join( [x, y, z] ), '1', '2', '3' ) )

Исходный пример:

logger.info('Stupid log message %s', Lazyfy(lambda: ' '.join((str(i) for i in range(20)))))

Как видите, это также охватываетдругой ответ, который использует лямбда-функцию, но использует больше памяти с атрибутом value и расширением.Тем не менее, он экономит больше памяти: Использование __slots __?

Наконец, наиболее эффективным решением остается следующее, как предлагается другой ответ:

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