How to track the time taken for each function in a route in Flask?

user_5168018 0
Viewed 1741

Right now I am trying to capture statistics of every request in flask, I am able to capture the time taken for a request to complete. Is there a way to capture the time taken for each function inside a route.

MY Code capturing the time taken by a route
@app.teardown_request
def teardown_func(response):
    print("tearing down reqest")
    print("Request",request)
    required_data = {
        "path": request.full_path,
        "url": request.url,
        "json_data": request.get_json(),
        "start": request.start_time,
        "stop": dt.utcnow(),
        "total_elapsed_time": (dt.utcnow() - request.start_time).total_seconds()
    }
    print("request data",required_data)
    return response

def call_func():
    sleep(5)
    print("FunctionCalled")

def another_func():
    sleep(5)
    print("FunctionCalled2")


@app.route('/',methods=['GET','POST'])
def hello2():
    time.sleep(10)
    call_func()
    another_func()
    return 'Hello World'

How do I calcualte that call_func() and another_func() took 5 seconds seach in the execution of that route?

flask python-2.7 logging python
1 Answers

One way is to use a decorator around functions you wish to time. The decorator will then add the name of the function with the elapsed running time of the function to a dictionary kept in the application global g attribute timings. This can be logged in a teardown_request or after_request hook or, as is done here, by the / view function:

from flask import Flask, Response, g
import time

app = Flask(__name__)

@app.before_request
def before_request_func():
    g.timings = {}

from functools import wraps
def time_this(func):
    @wraps(func)
    def wrapper(*args, **kwargs):
        start = time.time()
        r = func(*args, **kwargs)
        end = time.time()
        g.timings[func.__name__] = end - start
        return r
    return wrapper


@time_this
def call_func():
    time.sleep(1)

@time_this
def another_func():
    time.sleep(2)

@app.route('/',methods=['GET','POST'])
def hello2():
    call_func()
    another_func()
    return Response('Hello World: ' + str(g.timings), mimetype='text/plain')

Update

I just want to make the point that when you time a view function, the timing will not be created and added to the timings dictionary until after the function returns, so in that case the timings dictionary is best processed in an after_request hook function, for example:

@app.after_request
def after_request_func(response):
    # just append timings to the output response:
    response.data += ('\n' + str(g.timings)).encode('ascii')
    return response

@app.route('/',methods=['GET','POST'])
@time_this
def hello2():
    call_func()
    another_func()
    return Response('Hello World', mimetype='text/plain')

Outputs:

Hello World
{'call_func': 1.0014231204986572, 'another_func': 2.0004665851593018, 'hello2': 3.001889705657959}
user_28237190
Related