Search code examples
pythonflasklogging

How to measure Flask API response time and record them in logs?


I have a log system for my flask API

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__}")

And the logs look like:

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

However, I want to measure and record my flask API response time and add them to logs also, like 0.45 s, in order to see which API handler is slow.

The expecting behavior is like this:

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

Is there any method to conduct that? Thanks


Solution

  • You can use before_request and after_request to effect this on all routes. We'll make use of the g to store the start time of the request, and you can get the function name from request.endpoint.

    I haven't set up logging itself for this example, but it should be trivial to inject your own logging mechanism in, in place of print().

    from flask import Flask, g, request
    import time
    
    app = Flask(__name__)
    
    @app.before_request
    def log_route_start():
        g.start_time = time.time()
        
    @app.after_request
    def log_route_end(response):
        route = request.endpoint
        print(f"{route} ended after {time.time() - g.pop('start_time', None)}")
        return response
    
    @app.route('/test', methods=['GET'])
    def test():
        time.sleep(1)
        return "Hello"
    
    @app.route('/test2', methods=['GET'])
    def test2():
        time.sleep(0.5)
        return "Bye"
    
    if __name__ == '__main__':
        app.run(debug=True)