如何用Python logging输出增量时间而非绝对时间？

要实现每条日志显示与上一条的时间差，可以通过自定义logging.Filter来实现，核心思路是在Filter中维护上一次日志的时间戳，每次生成日志时计算时间差并注入到日志记录中，具体步骤如下：

1. 自定义时间增量Filter #

这个Filter会记录上一次日志的时间，每次处理日志时计算当前时间与上一次的差值，将差值存入日志记录的自定义字段：

import logging
import time

class DeltaTimeFilter(logging.Filter):
    def __init__(self):
        super().__init__()
        self.last_time = time.time()

    def filter(self, record):
        current_time = time.time()
        record.delta_time = current_time - self.last_time
        self.last_time = current_time
        return True

2. 配置日志并使用 #

修改日志配置，添加自定义Filter，同时调整日志格式，把增量时间字段%(delta_time).6f放到格式开头：

# 获取根logger
logger = logging.getLogger()
logger.setLevel(logging.INFO)

# 移除默认处理器（避免重复输出）
for handler in logger.handlers[:]:
    logger.removeHandler(handler)

# 创建控制台处理器
handler = logging.StreamHandler()
# 添加自定义Filter
handler.addFilter(DeltaTimeFilter())
# 设置日志格式，使用delta_time字段
formatter = logging.Formatter('%(delta_time).6f - %(levelname)s - %(message)s')
handler.setFormatter(formatter)

# 添加处理器到logger
logger.addHandler(handler)

# 测试日志输出
logger.info("Got a Chunk of Data in 1.662097 seconds")
time.sleep(0.008)
logger.info("Processed the Chunk in 0.008471 seconds")
time.sleep(0.003)
logger.info("Optimized the Data in 0.002940 seconds")

注意事项 #

• 这个实现仅适用于单线程场景，如果是多线程环境，多个线程同时写日志会导致时间计算混乱，此时需要给self.last_time的访问加上锁（比如用threading.Lock），但正如你所说，多线程下增量时间的意义不大。
• 初始的第一条日志的增量时间是从Filter初始化到第一条日志的时间差，如果需要第一条日志显示0，可以在初始化时把self.last_time设为第一条日志的时间，但通常第一条的启动时间差也有参考意义。

内容的提问来源于stack exchange，提问作者Krishna