Python日志模块 - 自上次日志以来的时间

Question

我想在 Python 的日志记录模块生成的日志中添加自上次记录日志以来经过的时间（秒/毫秒）。

这很有用，因此您可以查看日志文件以查看同一步骤是否总是花费相同的时间或发生变化，表明环境中发生了某些变化（例如数据库性能）。

我知道 %(relativeCreated)d，但这只是显示自记录器启动以来经过的时间，而不是自上次创建日志以来的时间。 基本上 %(relativeCreated)d 是累积值，我想看到的是每个 %(relativeCreated)d 之间的差异。

这就是你使用 %(relativeCreated)d 得到的结果：

2015-07-20 12:31:07,037 (7ms) - INFO - Process started....
2015-07-20 12:31:07,116 (87ms) - INFO - Starting working on xyz
2015-07-20 12:31:07,886 (857ms) - INFO - Progress so far

这就是我需要的：

2015-07-20 12:31:07,037 (duration: 7ms) - INFO - Process started....
2015-07-20 12:31:07,116 (duration: 80ms) - INFO - Starting working on xyz
2015-07-20 12:31:07,886 (duration: 770ms) - INFO - Progress so far

Answer 1

扩展来自@Simeon Visser 的答案——过滤器是一个简单的存储设备，用于存储自脚本启动以来最后一条消息的相对时间（参见TimeFilter 类中的self.last）。

import datetime
import logging

class TimeFilter(logging.Filter):

    def filter(self, record):
        try:
          last = self.last
        except AttributeError:
          last = record.relativeCreated

        delta = datetime.datetime.fromtimestamp(record.relativeCreated/1000.0) - datetime.datetime.fromtimestamp(last/1000.0)

        record.relative = '{0:.2f}'.format(delta.seconds + delta.microseconds/1000000.0)

        self.last = record.relativeCreated
        return True

然后将该过滤器应用于每个日志处理程序，并访问每个日志处理程序的日志格式字符串中的相对时间。

fmt = logging.Formatter(fmt="%(asctime)s (%(relative)ss) %(message)s")
log = logging.getLogger()
[hndl.addFilter(TimeFilter()) for hndl in log.handlers]
[hndl.setFormatter(fmt) for hndl in log.handlers]

Answer 2

这可以使用自定义logging.Filter 实例来完成。这是一个使用 logaugment 库的示例，或者您可以查看 at the source 来构建类似的东西。

import datetime
import logging

import logaugment

logger = logging.getLogger()
handler = logging.StreamHandler()
formatter = logging.Formatter("%(time_since_last)s: %(message)s")
handler.setFormatter(formatter)
logger.addHandler(handler)

创建记录器后，您需要指定一个函数，该函数将在每次创建记录记录时调用：

def process_record(record):
    now = datetime.datetime.utcnow()
    try:
        delta = now - process_record.now
    except AttributeError:
        delta = 0
    process_record.now = now
    return {'time_since_last': delta}

logaugment.add(logger, process_record)
logger.warn("My message")

例子：

# 0:00:02.127129: My message

这会将datetime.timedelta 对象转换为字符串。您可以使用以下格式将其格式化为以毫秒为单位的值：

try:
    formatted = '{}ms'.format(delta.total_seconds() * 1000)
except AttributeError:
    formatted = '0ms'
return {'time_since_last': formatted}

这需要 Python 2.7+（对于 total_seconds()）。