Python记录程序运行时间

Question

我正在使用 logging 模块创建日志记录器并输出数据。在 logging.Formatter 中，我想记录相对于记录器创建时间的时间戳，而不是使用 $(asctime)s。是否有好的方法实现此功能？

- dpington

Answer 1

在传统的格式化格式字符串中使用%(relativeCreated)d字段将显示自加载logging模块以来经过的毫秒数。虽然毫秒可能不是您想要的，但无需进行额外编码。

- Vinay Sajip

Answer 2

您可以编写自己的格式化程序：

from datetime import timedelta
import logging
import time

class ElapsedFormatter():

    def __init__(self):
        self.start_time = time.time()

    def format(self, record):
        elapsed_seconds = record.created - self.start_time
        #using timedelta here for convenient default formatting
        elapsed = timedelta(seconds = elapsed_seconds)
        return "{} {}".format(elapsed, record.getMessage())

#add custom formatter to root logger for simple demonstration
handler = logging.StreamHandler()
handler.setFormatter(ElapsedFormatter())
logging.getLogger().addHandler(handler)

log = logging.getLogger('test')
log.error("Message 1")

time.sleep(5)

log.error("Message 2")

你的问题涉及到从“程序开始”以及“创建记录器”开始经过的时间，这可能意味着不同的事情。

这将测量从创建CustomFormatter开始经过的时间，你可以在程序开始时或创建记录器时进行。

- Jeremy Allen

---

谢谢这个提示。我使用了time.clock()而不是timedelta。不知道这样做是否有任何权衡，但计算会更简单一些。 - Samuel

Answer 3

我喜欢Franky1的答案，但是我不想失去日志格式中的%(asctime)s风格。这里提供了一种解决方案，可以添加%(delta)s样式。

import datetime
import logging
import time

class DeltaTimeFormatter(logging.Formatter):
    def format(self, record):
        duration = datetime.datetime.utcfromtimestamp(record.relativeCreated / 1000)
        record.delta = duration.strftime("%H:%M:%S")
        return super().format(record)

# add custom formatter to root logger
handler = logging.StreamHandler()
LOGFORMAT = '+%(delta)s - %(asctime)s - %(levelname)-9s: %(message)s'
fmt = DeltaTimeFormatter(LOGFORMAT)
handler.setFormatter(fmt)
logging.getLogger().addHandler(handler)
logger = logging.getLogger()

# test of the logger output
logger.error('Test')
for sleep in (1, 2, 3, 4, 5):
    time.sleep(sleep)
    logger.error('logging')

- Keith

Answer 4

我根据一些stackoverflow的想法，自己编写了解决方案。
它是logging.Formatter的一个子类。

import datetime
import logging
import time

# subclass of logging.Formatter
class RuntimeFormatter(logging.Formatter):
    def __init__(self, *args, **kwargs):
        super().__init__(*args, **kwargs)
        self.start_time = time.time()
    def formatTime(self, record, datefmt=None):
        duration = datetime.datetime.utcfromtimestamp(record.created - self.start_time)
        elapsed = duration.strftime('%H:%M:%S')
        return "{}".format(elapsed)

# add custom formatter to root logger
LOGFORMAT = '%(asctime)s - %(levelname)-9s: %(message)s'
handler = logging.StreamHandler()
fmt = RuntimeFormatter(LOGFORMAT)
handler.setFormatter(fmt)
logging.getLogger().addHandler(handler)
logger = logging.getLogger()

# test of the logger output
logger.error('Test')

- Franky1