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

Я использую стандартный модуль ведения журнала 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) нет макросов, если есть эффективный способ ведения журнала?

5 56
python logging

5 ответов:

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

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 () вызов попал в ошибку утверждения, в то время как регистратор.debug () не зашел так далеко.

66

конечно, не так эффективно, как макрос:

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 для моей установки.

31
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 секунд. Это показывает, что аргумент не вычисляется, когда уровень ведения журнала ниже установленного уровня.

24

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

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__ метод.

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

13

Я представляю, 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 атрибут и расширение. Тем не менее, это экономит больше памяти с: использование __слот__?

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

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