Adding response elpased time to logs

I was wondering if there’s a way to add the elapsed time for each response to the logs. I tried to implement the very basic version of this feature:

index 8e55a6b..28310c0 100644
--- a/uvicorn/logging.py
+++ b/uvicorn/logging.py
@@ -106,7 +106,13 @@ class AccessFormatter(ColourizedFormatter):
         client_addr = self.get_client_addr(scope)
         status_code = self.get_status_code(record)
         http_version = scope["http_version"]
-        request_line = "%s %s HTTP/%s" % (method, full_path, http_version)
+        elapsed_time = record.__dict__["elapsed"]
+        request_line = "%s %s HTTP/%s in %s msecs" % (
+            method,
+            full_path,
+            http_version,
+            elapsed_time,
+        )
         if self.use_colors:
             request_line = click.style(request_line, bold=True)
         record.__dict__.update(
@@ -118,6 +124,7 @@ class AccessFormatter(ColourizedFormatter):
                 "request_line": request_line,
                 "status_code": status_code,
                 "http_version": http_version,
+                "elapsed": elapsed_time,
             }
         )
         return super().formatMessage(record)
diff --git a/uvicorn/protocols/http/httptools_impl.py b/uvicorn/protocols/http/httptools_impl.py
index ebc7667..4bea9d7 100644
--- a/uvicorn/protocols/http/httptools_impl.py
+++ b/uvicorn/protocols/http/httptools_impl.py
@@ -1,3 +1,4 @@
+import time
 import asyncio
 import http
 import logging
@@ -374,6 +375,7 @@ class RequestResponseCycle:
         self.more_body = True
 
         # Response state
+        self.start = None
         self.response_started = False
         self.response_complete = False
         self.chunked_encoding = None
@@ -442,6 +444,7 @@ class RequestResponseCycle:
 
             status_code = message["status"]
             headers = self.default_headers + list(message.get("headers", []))
+            elapsed = int((time.time() - self.start) * 1000)
 
             if self.access_log:
                 self.access_logger.info(
@@ -451,7 +454,10 @@ class RequestResponseCycle:
                     get_path_with_query_string(self.scope),
                     self.scope["http_version"],
                     status_code,
-                    extra={"status_code": status_code, "scope": self.scope},
+                    extra={
+                        "status_code": status_code,
+                        "scope": self.scope,
+                        "elapsed": elapsed},
                 )
 
             # Write response status line and headers
@@ -542,5 +548,5 @@ class RequestResponseCycle:
                 "more_body": self.more_body,
             }
             self.body = b""
-
+        self.start = time.time()
         return message

This would change info logs to:

INFO:     127.0.0.1:59216 - "GET /api/static/admin/css/base.css HTTP/1.1 in 3 msecs" 304 Not Modified
INFO:     127.0.0.1:59218 - "GET /api/static/admin/css/login.css HTTP/1.1 in 13 msecs" 304 Not Modified

Would it be interesting for anyone else? if so then I’d be very happy to open a PR and probably clean up the code and add tests.

Hey there, any luck timing-asgi could fit your use case? It logs the elapsed time with some other info, although separately from uvicorn (which is probably okay?).

I’m using uvicorn to serve a Django app not Starlette app, so not sure if timing-asgi works with that too. Actually I wanted find out if there’s a reason for not having timing inside uvicorn itself. Or find a way to make it an optional middleware, but still inside the uvicorn package.