Add .elapsed onto Response objects tracking how long a request took. (#351)

* Add `.elapsed` onto Response objects tracking how long a request took.

* Move elapsed timing from send methods into _get_response

* Address feedback

* Update tests/test_api.py

Co-Authored-By: Florimond Manca <florimond.manca@gmail.com>

docs/api.md

@@ -59,6 +59,11 @@
 * `.request` - **Request**
 * `.cookies` - **Cookies**
 * `.history` - **List[Response]**
+* `.elapsed` - **[timedelta](https://docs.python.org/3/library/datetime.html)**
+  * The amount of time elapsed between sending the first byte and parsing the headers (not including time spent reading
+  the response).  Use
+  [total_seconds()](https://docs.python.org/3/library/datetime.html#datetime.timedelta.total_seconds) to correctly get
+  the total elapsed seconds.
 * `def .raise_for_status()` - **None**
 * `def .json()` - **Any**
 * `def .read()` - **bytes**

httpx/client.py

@@ -45,7 +45,7 @@ from .models import (
     ResponseContent,
     URLTypes,
 )
-from .utils import get_netrc_login
+from .utils import ElapsedTimer, get_netrc_login
 
 
 class BaseClient:
@@ -168,9 +168,11 @@ class BaseClient:
 
         async def get_response(request: AsyncRequest) -> AsyncResponse:
             try:
-                response = await self.dispatch.send(
-                    request, verify=verify, cert=cert, timeout=timeout
-                )
+                with ElapsedTimer() as timer:
+                    response = await self.dispatch.send(
+                        request, verify=verify, cert=cert, timeout=timeout
+                    )
+                response.elapsed = timer.elapsed
             except HTTPError as exc:
                 # Add the original request to any HTTPError
                 exc.request = request
@@ -707,6 +709,7 @@ class Client(BaseClient):
             on_close=sync_on_close,
             request=async_response.request,
             history=async_response.history,
+            elapsed=async_response.elapsed,
         )
         if not stream:
             try:

httpx/models.py

@@ -1,4 +1,5 @@
 import cgi
+import datetime
 import email.message
 import json as jsonlib
 import typing
@@ -717,6 +718,7 @@ class BaseResponse:
         headers: HeaderTypes = None,
         request: BaseRequest = None,
         on_close: typing.Callable = None,
+        elapsed: datetime.timedelta = None,
     ):
         self.status_code = status_code
         self.http_version = http_version
@@ -724,6 +726,7 @@ class BaseResponse:
 
         self.request = request
         self.on_close = on_close
+        self.elapsed = datetime.timedelta(0) if elapsed is None else elapsed
         self.call_next: typing.Optional[typing.Callable] = None
 
     @property
@@ -901,6 +904,7 @@ class AsyncResponse(BaseResponse):
         on_close: typing.Callable = None,
         request: AsyncRequest = None,
         history: typing.List["BaseResponse"] = None,
+        elapsed: datetime.timedelta = None,
     ):
         super().__init__(
             status_code=status_code,
@@ -908,6 +912,7 @@ class AsyncResponse(BaseResponse):
             headers=headers,
             request=request,
             on_close=on_close,
+            elapsed=elapsed,
         )
 
         self.history = [] if history is None else list(history)
@@ -1000,6 +1005,7 @@ class Response(BaseResponse):
         on_close: typing.Callable = None,
         request: Request = None,
         history: typing.List["BaseResponse"] = None,
+        elapsed: datetime.timedelta = None,
     ):
         super().__init__(
             status_code=status_code,
@@ -1007,6 +1013,7 @@ class Response(BaseResponse):
             headers=headers,
             request=request,
             on_close=on_close,
+            elapsed=elapsed,
         )
 
         self.history = [] if history is None else list(history)

httpx/utils.py

@@ -5,7 +5,10 @@ import os
 import re
 import sys
 import typing
+from datetime import timedelta
 from pathlib import Path
+from time import perf_counter
+from types import TracebackType
 
 
 def normalize_header_key(value: typing.AnyStr, encoding: str = None) -> bytes:
@@ -183,3 +186,27 @@ def to_str(str_or_bytes: typing.Union[str, bytes], encoding: str = "utf-8") -> s
 
 def unquote(value: str) -> str:
     return value[1:-1] if value[0] == value[-1] == '"' else value
+
+
+class ElapsedTimer:
+    def __init__(self) -> None:
+        self.start: float = perf_counter()
+        self.end: typing.Optional[float] = None
+
+    def __enter__(self) -> "ElapsedTimer":
+        self.start = perf_counter()
+        return self
+
+    def __exit__(
+        self,
+        exc_type: typing.Type[BaseException] = None,
+        exc_value: BaseException = None,
+        traceback: TracebackType = None,
+    ) -> None:
+        self.end = perf_counter()
+
+    @property
+    def elapsed(self) -> timedelta:
+        if self.end is None:
+            return timedelta(seconds=perf_counter() - self.start)
+        return timedelta(seconds=self.end - self.start)

tests/client/test_async_client.py

@@ -1,3 +1,5 @@
+from datetime import timedelta
+
 import pytest
 
 import httpx
@@ -12,6 +14,7 @@ async def test_get(server, backend):
     assert response.http_version == "HTTP/1.1"
     assert response.headers
     assert repr(response) == "<Response [200 OK]>"
+    assert response.elapsed > timedelta(seconds=0)
 
 
 async def test_build_request(server, backend):

tests/client/test_client.py

@@ -1,3 +1,6 @@
+from datetime import timedelta
+from time import sleep
+
 import pytest
 
 import httpx
@@ -17,6 +20,7 @@ def test_get(server):
     assert response.headers
     assert response.is_redirect is False
     assert repr(response) == "<Response [200 OK]>"
+    assert response.elapsed > timedelta(0)
 
 
 def test_build_request(server):
@@ -156,3 +160,17 @@ def test_client_backend_must_be_asyncio_based():
 
     with pytest.raises(ValueError):
         httpx.Client(backend=AnyBackend())
+
+
+def test_elapsed_delay(server):
+    with httpx.Client() as http:
+        response = http.get(server.url.copy_with(path="/slow_response/100"))
+    assert response.elapsed.total_seconds() == pytest.approx(0.1, abs=0.01)
+
+
+def test_elapsed_delay_ignores_read_time(server):
+    with httpx.Client() as http:
+        response = http.get(server.url.copy_with(path="/slow_response/50"), stream=True)
+    sleep(0.1)
+    response.read()
+    assert response.elapsed.total_seconds() == pytest.approx(0.05, abs=0.01)

tests/conftest.py

@@ -53,7 +53,7 @@ def backend(request):
 
 async def app(scope, receive, send):
     assert scope["type"] == "http"
-    if scope["path"] == "/slow_response":
+    if scope["path"].startswith("/slow_response"):
         await slow_response(scope, receive, send)
     elif scope["path"].startswith("/status"):
         await status_code(scope, receive, send)
@@ -77,7 +77,12 @@ async def hello_world(scope, receive, send):
 
 
 async def slow_response(scope, receive, send):
-    await asyncio.sleep(0.1)
+    delay_ms_str: str = scope["path"].replace("/slow_response/", "")
+    try:
+        delay_ms = float(delay_ms_str)
+    except ValueError:
+        delay_ms = 100
+    await asyncio.sleep(delay_ms / 1000.0)
     await send(
         {
             "type": "http.response.start",

tests/models/test_responses.py

@@ -1,3 +1,4 @@
+import datetime
 import json
 from unittest import mock
 
@@ -21,6 +22,7 @@ def test_response():
     assert response.status_code == 200
     assert response.reason_phrase == "OK"
     assert response.text == "Hello, world!"
+    assert response.elapsed == datetime.timedelta(0)
 
 
 def test_response_repr():

tests/test_utils.py

@@ -1,3 +1,4 @@
+import asyncio
 import logging
 import os
 
@@ -5,7 +6,12 @@ import pytest
 
 import httpx
 from httpx import utils
-from httpx.utils import get_netrc_login, guess_json_utf, parse_header_links
+from httpx.utils import (
+    ElapsedTimer,
+    get_netrc_login,
+    guess_json_utf,
+    parse_header_links,
+)
 
 
 @pytest.mark.parametrize(
@@ -111,3 +117,14 @@ async def test_httpx_debug_enabled_stderr_logging(server, capsys, httpx_debug):
 
     # Reset the logger so we don't have verbose output in all unit tests
     logging.getLogger("httpx").handlers = []
+
+
+@pytest.mark.asyncio
+async def test_elapsed_timer():
+    with ElapsedTimer() as timer:
+        assert timer.elapsed.total_seconds() == pytest.approx(0, abs=0.05)
+        await asyncio.sleep(0.1)
+    await asyncio.sleep(
+        0.1
+    )  # test to ensure time spent after timer exits isn't accounted for.
+    assert timer.elapsed.total_seconds() == pytest.approx(0.1, abs=0.05)