Оценка строки ленивого журнала

Я использую стандартный модуль регистрации 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

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

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

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

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

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

Ответы

Ответ 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() не так далеко.

Ответ 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.

Ответ 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

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

Ответ 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__.

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

Ответ 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)]))

Ответ 6

Если вы зависите только от доступа к глобальным атрибутам состояния, вы можете создать экземпляр класса python и lazify его с помощью метода __str__:

class get_lazy_debug(object):
    def __repr__(self):
        return ' '.join(
                str(i) for i in range(20)
            )

# Allows to pass get_lazy_debug as a function parameter without 
# evaluating/creating its string!
get_lazy_debug = get_lazy_debug()

logger.debug( 'Stupid log message', get_lazy_debug )

Связанный: