如何测量Flask API响应时间并将其记录到现有日志中？

现有实现 #

我为Flask API搭建了一套日志系统，相关Python代码如下：

import logging

def setup_logger(logp=None, debug=False):
    log_level = logging.DEBUG if debug else logging.INFO
    form = "[%(asctime)s][%(name)s][%(levelname)s][%(filename)s] %(message)s"
    datefmt = "%Y-%m-%d-%H:%M:%S"
    logging.basicConfig(level=log_level, format=form, datefmt=datefmt)
    if logp is not None:
        fhandler = logging.StreamHandler(open(logp, 'a'))
        fhandler.setFormatter(logging.Formatter(form, datefmt))
        logging.root.addHandler(fhandler)


logger = logging.getLogger("MY_APP")
setup_logger()
logger.debug(f"Import {__file__}")

当前日志格式：

[2024-04-19-04:20:02][werkzeug][INFO][_internal.py] 172.23.0.2 - - [19/Apr/2024 04:20:02] "GET /available/space HTTP/1.1" 200 -

需求 #

希望测量并记录Flask API的响应时间（如0.45 s），添加到日志中，期望日志格式：

[2024-04-19-04:20:02][werkzeug][INFO][_internal.py][0.45 s] 172.23.0.2 - - [19/Apr/2024 04:20:02] "GET /available/space HTTP/1.1" 200 -

方法一：使用Flask请求钩子 #

利用Flask的before_request和after_request钩子，在请求生命周期的首尾记录并计算耗时，再修改日志格式插入响应时间：

from flask import Flask, request
import time
import logging

app = Flask(__name__)

# 请求开始前记录时间戳
@app.before_request
def start_timer():
    request.start_time = time.time()

# 请求结束后计算耗时并更新日志格式
@app.after_request
def log_response_time(response):
    if hasattr(request, 'start_time'):
        elapsed_time = time.time() - request.start_time
        elapsed_str = f"{elapsed_time:.2f} s"
        
        # 给werkzeug日志器添加响应时间字段
        werkzeug_logger = logging.getLogger('werkzeug')
        for handler in werkzeug_logger.handlers:
            fmt = handler.formatter._fmt
            if '[%(response_time)s]' not in fmt:
                handler.formatter._fmt = fmt.replace('] %(message)s', '][%(response_time)s] %(message)s')
        
        # 将耗时传入日志上下文
        werkzeug_logger.info('', extra={'response_time': elapsed_str})
    
    return response

# 示例API路由
@app.route('/available/space')
def available_space():
    time.sleep(0.45)  # 模拟业务耗时
    return "OK", 200

# 原有日志初始化代码
def setup_logger(logp=None, debug=False):
    log_level = logging.DEBUG if debug else logging.INFO
    form = "[%(asctime)s][%(name)s][%(levelname)s][%(filename)s] %(message)s"
    datefmt = "%Y-%m-%d-%H:%M:%S"
    logging.basicConfig(level=log_level, format=form, datefmt=datefmt)
    if logp is not None:
        fhandler = logging.StreamHandler(open(logp, 'a'))
        fhandler.setFormatter(logging.Formatter(form, datefmt))
        logging.root.addHandler(fhandler)

setup_logger()

if __name__ == '__main__':
    app.run(host='0.0.0.0', port=5000)

方法二：自定义日志过滤器 #

通过自定义日志过滤器，在日志输出时自动注入响应时间，无需修改钩子内的日志逻辑：

from flask import Flask, request
import time
import logging

app = Flask(__name__)

# 自定义过滤器，注入响应时间
class ResponseTimeFilter(logging.Filter):
    def filter(self, record):
        if hasattr(request, 'start_time'):
            elapsed_time = time.time() - request.start_time
            record.response_time = f"{elapsed_time:.2f} s"
        else:
            record.response_time = "-"  # 无时间记录时的默认值
        return True

# 修改日志初始化逻辑，添加过滤器和响应时间字段
def setup_logger(logp=None, debug=False):
    log_level = logging.DEBUG if debug else logging.INFO
    # 日志格式直接加入响应时间字段
    form = "[%(asctime)s][%(name)s][%(levelname)s][%(filename)s][%(response_time)s] %(message)s"
    datefmt = "%Y-%m-%d-%H:%M:%S"
    logging.basicConfig(level=log_level, format=form, datefmt=datefmt)
    
    # 给werkzeug日志器添加过滤器
    werkzeug_logger = logging.getLogger('werkzeug')
    werkzeug_logger.addFilter(ResponseTimeFilter())
    
    if logp is not None:
        fhandler = logging.StreamHandler(open(logp, 'a'))
        fhandler.setFormatter(logging.Formatter(form, datefmt))
        fhandler.addFilter(ResponseTimeFilter())
        logging.root.addHandler(fhandler)

# 请求开始前记录时间戳
@app.before_request
def start_timer():
    request.start_time = time.time()

# 示例API路由
@app.route('/available/space')
def available_space():
    time.sleep(0.45)  # 模拟业务耗时
    return "OK", 200

setup_logger()

if __name__ == '__main__':
    app.run(host='0.0.0.0', port=5000)

关键注意点 #

• 两种方法核心都是在请求开始时记录时间戳，结束时计算耗时，再将耗时注入日志格式。
• Flask默认的请求日志由werkzeug日志器输出，因此需要针对该日志器做格式或过滤器修改。
• 可以调整elapsed_time:.2f中的小数位数，来控制响应时间的精度。

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