Today, I spent a while trying to debug a slow API endpoint. As part of the initial exploratory process, I just wanted to time how long the entire request/response cycle was taking. This is simple enough with time curl ... in the shell, but for convenience, I wanted it in my Django logs.

The technique I settled on is fairly obvious in hindsight, since everything is an object in Python, but it never really occurred to me until today: why not just slap some timers on the request in middleware?

I ended up with something like this:

def process_request(self, request):
    request.start_time = time.time()

def process_view(self, request, view_func, view_args, view_kwargs):
        request.view_name = getattr(view_func, '__name__', repr(view_func))

def process_response(self, request, response):
    total_time = round(time.time()-request.start_time, 1)
    print(f"⏰ \033[1;36m{request.view_name}\033[0m total response time: {total_time} seconds")

Now my logs look something like this (omitted some stuff from the above code snippet):

Response time still slow. 🙃 But at least the logs are pretty!