惰性记录器消息字符串评估

发布于 2024-10-02 07:13:11 字数 597 浏览 10 评论 0原文

我在 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（记录器，消息）
这实际上等于

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

但是由于Python中没有宏（据我所知），是否有一种有效的方法来进行日志记录？

原文

I'm using standard python logging module in my python application:

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

The issue is that although debug level is not enable, that stupid log message is evaluated on each loop iteration, which harms performance badly.

Is there any solution for this?

In C++ we have log4cxx package that provides macros like this:
LOG4CXX_DEBUG(logger, messasage)
That effectively evaluates to

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

But since there are no macros in Python (AFAIK), if there a efficient way to do logging?

分享到QQ

分享到微博

如果你对这篇内容有疑问，欢迎到本站社区发帖提问参与讨论，获取更多帮助，或者扫码二维码加入 Web 技术交流群。

发布评论

需要登录才能够评论，你可以免费注册一个本站的账号。

水中月 2024-10-09 07:13:11

日志记录模块已经部分支持您想要做的事情。这样做：

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

...而不是这样：

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

日志记录模块足够聪明，不会生成完整的日志消息，除非该消息实际上被记录在某处。

要将此功能应用于您的特定请求，您可以创建一个惰性连接类。

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() 则没有达到这一点。

The logging module already has partial support for what you want to do. Do this:

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

... instead of this:

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

The logging module is smart enough to not produce the complete log message unless the message actually gets logged somewhere.

To apply this feature to your specific request, you could create a lazyjoin class.

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

Use it like this (note the use of a generator expression, adding to the laziness):

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

Here is a demo that shows this works.

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

In the demo, The logger.info() call hit the assertion error, while logger.debug() did not get that far.

回复收藏 0 原文

古镇旧梦 2024-10-09 07:13:11

当然，以下内容不如宏高效：

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 了解我的设置。

Of course the following is not as efficient as a Macro:

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

but simple, evaluates in lazy fashion and is 4 times faster than the accepted answer:

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

See benchmark-src for my setup.

回复收藏 0 原文

腹黑女流氓 2024-10-09 07:13:11

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 秒即可执行。这表明当日志记录级别低于设置级别时，不会评估参数。

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

If you run the script, you'll notice the first logger.debug command does not take 20 seconds to execute. This shows the argument is not evaluated when the logging level is below the set level.

回复收藏 0 原文

蓝色星空 2024-10-09 07:13:11

正如 Shane 指出的，使用

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() 也会被计算。

解决方案是使用 lambda 函数，但这需要一些额外的机制：

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

在这种情况下，lambda 函数将仅在以下情况下被调用：log.debug 决定执行格式化，因此调用 __str__ 方法。

请注意：该解决方案的开销很可能超过收益:-) 但至少在理论上，它使得完全惰性日志记录成为可能。

As Shane points out, using

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

... instead of this:

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

saves some time by only performing the string formatting if the message is actually logged.

This does not completely solve the problem, though, as you may have to pre-process the values to format into the string, such as:

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

In that case, obj.get_a() and obj.get_b() will be computed even if no logging happens.

A solution to that would be to use lambda functions, but this requires some extra machinery:

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

... then you can log with the following:

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

In that case, the lambda function will only be called if log.debug decides to perform the formatting, hence calling the __str__ method.

Mind you: the overhead of that solution may very well exceed the benefit :-) But at least in theory, it makes it possible to do perfectly lazy logging.

回复收藏 0 原文

回忆追雨的时光 2024-10-09 07:13:11

我提出，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)))))

如您所见，这也涵盖了使用 lambda 函数的其他答案，但使用 value 属性和扩展使用更多内存。但是，它可以通过以下方式节省更多内存： Usage of __slots__?

最后，到目前为止，最有效的解决方案仍然是正如另一个答案所建议的那样：

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

I present, 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)

Usage:

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

The original example:

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

As you see, this also covers the other answer which uses lambda function, but uses more memory with the value atribute and expansion. However, it saves more memory with: Usage of __slots__?

Finally, by far, the most efficient solution still being the following as suggested another answer:

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

回复收藏 0 原文

一念一轮回 2024-10-09 07:13:11

如果您仅依赖于访问全局状态属性，则可以实例化一个 python 类并使用 __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 )