diff --git a/uvicorn/logging.py b/uvicorn/logging.py index de1a9e9bf0..4aa32ab467 100644 --- a/uvicorn/logging.py +++ b/uvicorn/logging.py @@ -130,8 +130,9 @@ class GunicornSafeAtoms(abc.Mapping): - escapes double quotes found in atom strings """ - def __init__(self, scope): + def __init__(self, scope, timing): self.scope = scope + self.timing = timing self.status_code = None self.response_headers = {} self.response_length = 0 @@ -148,8 +149,7 @@ def request_headers(self): @property def duration(self): - d = self.scope["response_end_time"] - self.scope["request_start_time"] - return d + return self.timing.total_duration_seconds() def on_asgi_message(self, message): if message["type"] == "http.response.start": diff --git a/uvicorn/protocols/http/h11_impl.py b/uvicorn/protocols/http/h11_impl.py index e1561e6fb7..026d6be7b9 100644 --- a/uvicorn/protocols/http/h11_impl.py +++ b/uvicorn/protocols/http/h11_impl.py @@ -1,7 +1,6 @@ import asyncio import http import logging -import time import traceback from typing import Callable from urllib.parse import unquote @@ -17,6 +16,7 @@ service_unavailable, ) from uvicorn.protocols.utils import ( + RequestResponseTiming, get_client_addr, get_local_addr, get_path_with_query_string, @@ -174,11 +174,6 @@ def handle_events(self): "raw_path": raw_path, "query_string": query_string, "headers": self.headers, - "extensions": { - "uvicorn_request_duration": { - "request_start_time": time.monotonic(), - } - }, } for name, value in self.headers: @@ -212,6 +207,7 @@ def handle_events(self): message_event=asyncio.Event(), on_response=self.on_response_complete, ) + self.cycle.timing.request_started() task = self.loop.create_task(self.cycle.run_asgi(app)) task.add_done_callback(self.tasks.discard) self.tasks.add(task) @@ -229,6 +225,7 @@ def handle_events(self): self.transport.resume_reading() self.conn.start_next_cycle() continue + self.cycle.timing.request_ended() self.cycle.more_body = False self.cycle.message_event.set() @@ -373,10 +370,11 @@ def __init__( # Response state self.response_started = False self.response_complete = False + self.timing = RequestResponseTiming() # For logging if self.gunicorn_log: - self.gunicorn_atoms = GunicornSafeAtoms(self.scope) + self.gunicorn_atoms = GunicornSafeAtoms(self.scope, self.timing) else: self.gunicorn_atoms = None @@ -443,6 +441,7 @@ async def send(self, message): self.response_started = True self.waiting_for_100_continue = False + self.timing.response_started() status_code = message["status"] headers = self.default_headers + message.get("headers", []) @@ -492,8 +491,7 @@ async def send(self, message): event = h11.EndOfMessage() output = self.conn.send(event) - duration_scope = self.scope["extensions"]["uvicorn_request_duration"] - duration_scope["response_end_time"] = time.monotonic() + self.timing.response_ended() if self.gunicorn_log is not None: try: self.gunicorn_log.access_log.info( diff --git a/uvicorn/protocols/http/httptools_impl.py b/uvicorn/protocols/http/httptools_impl.py index e5e8d329fa..6e63bf5bd4 100644 --- a/uvicorn/protocols/http/httptools_impl.py +++ b/uvicorn/protocols/http/httptools_impl.py @@ -18,6 +18,7 @@ service_unavailable, ) from uvicorn.protocols.utils import ( + RequestResponseTiming, get_client_addr, get_local_addr, get_path_with_query_string, @@ -86,6 +87,7 @@ def __init__( self.headers = None self.expect_100_continue = False self.cycle = None + self.request_start_time = None # Protocol interface def connection_made(self, transport): @@ -211,13 +213,11 @@ def on_url(self, url): "raw_path": raw_path, "query_string": parsed_url.query if parsed_url.query else b"", "headers": self.headers, - "extensions": { - "uvicorn_request_duration": { - "request_start_time": time.monotonic(), - } - }, } + def on_message_begin(self): + self.request_start_time = time.monotonic() + def on_header(self, name: bytes, value: bytes): name = name.lower() if name == b"expect" and value.lower() == b"100-continue": @@ -257,6 +257,7 @@ def on_headers_complete(self): keep_alive=http_version != "1.0", on_response=self.on_response_complete, ) + self.cycle.timing.request_start_time = self.request_start_time if existing_cycle is None or existing_cycle.response_complete: # Standard case - start processing the request. task = self.loop.create_task(self.cycle.run_asgi(app)) @@ -280,6 +281,7 @@ def on_message_complete(self): return self.cycle.more_body = False self.cycle.message_event.set() + self.cycle.timing.request_ended() def on_response_complete(self): # Callback for pipelined HTTP requests to be started. @@ -376,10 +378,11 @@ def __init__( self.response_complete = False self.chunked_encoding = None self.expected_content_length = 0 + self.timing = RequestResponseTiming() # For logging. if self.gunicorn_log: - self.gunicorn_atoms = GunicornSafeAtoms(self.scope) + self.gunicorn_atoms = GunicornSafeAtoms(self.scope, self.timing) else: self.gunicorn_atoms = None @@ -445,6 +448,7 @@ async def send(self, message): raise RuntimeError(msg % message_type) self.response_started = True + self.timing.response_started() self.waiting_for_100_continue = False status_code = message["status"] @@ -528,8 +532,7 @@ async def send(self, message): if self.expected_content_length != 0: raise RuntimeError("Response content shorter than Content-Length") self.response_complete = True - duration_scope = self.scope["extensions"]["uvicorn_request_duration"] - duration_scope["response_end_time"] = time.monotonic() + self.timing.response_ended() if self.gunicorn_log is not None: try: diff --git a/uvicorn/protocols/utils.py b/uvicorn/protocols/utils.py index bbc84f7aa9..e04c3a767c 100644 --- a/uvicorn/protocols/utils.py +++ b/uvicorn/protocols/utils.py @@ -1,4 +1,5 @@ import asyncio +import time import urllib.parse from typing import Optional, Tuple @@ -54,3 +55,32 @@ def get_path_with_query_string(scope: WWWScope) -> str: path_with_query_string, scope["query_string"].decode("ascii") ) return path_with_query_string + + +class RequestResponseTiming: + def __init__(self): + self.request_start_time: Optional[int] = None + self.request_end_time: Optional[int] = None + self.response_start_time: Optional[int] = None + self.response_end_time: Optional[int] = None + + def request_started(self): + self.request_start_time = time.monotonic() + + def request_ended(self): + self.request_end_time = time.monotonic() + + def response_started(self): + self.response_start_time = time.monotonic() + + def response_ended(self): + self.response_end_time = time.monotonic() + + def request_duration_seconds(self): + return self.request_end_time - self.request_start_time + + def response_duration_seconds(self): + return self.response_end_time - self.response_start_time + + def total_duration_seconds(self): + return self.response_end_time - self.request_start_time