diff --git a/packages/service-library/src/servicelib/aiohttp/monitoring.py b/packages/service-library/src/servicelib/aiohttp/monitoring.py index b46dcde79c9..1c89b89ffd1 100644 --- a/packages/service-library/src/servicelib/aiohttp/monitoring.py +++ b/packages/service-library/src/servicelib/aiohttp/monitoring.py @@ -2,8 +2,8 @@ import asyncio import logging -import time from collections.abc import Awaitable, Callable +from time import perf_counter from typing import Final from aiohttp import web @@ -67,7 +67,7 @@ async def middleware_handler(request: web.Request, handler: Handler): canonical_endpoint = request.path if request.match_info.route.resource: canonical_endpoint = request.match_info.route.resource.canonical - start_time = time.time() + start_time = perf_counter() try: if enter_middleware_cb: with log_catch(logger=log, reraise=False): @@ -111,7 +111,7 @@ async def middleware_handler(request: web.Request, handler: Handler): raise resp from exc finally: - resp_time_secs: float = time.time() - start_time + response_latency_seconds = perf_counter() - start_time record_response_metrics( metrics=metrics, @@ -119,6 +119,7 @@ async def middleware_handler(request: web.Request, handler: Handler): endpoint=canonical_endpoint, user_agent=user_agent, http_status=resp.status, + response_latency_seconds=response_latency_seconds, ) if exit_middleware_cb: @@ -133,7 +134,7 @@ async def middleware_handler(request: web.Request, handler: Handler): request.remote, request.method, request.path, - resp_time_secs, + response_latency_seconds, resp.status, exc_info=log_exception, stack_info=True, diff --git a/packages/service-library/src/servicelib/fastapi/monitoring.py b/packages/service-library/src/servicelib/fastapi/monitoring.py index 89a29b0642a..32dd26f53d6 100644 --- a/packages/service-library/src/servicelib/fastapi/monitoring.py +++ b/packages/service-library/src/servicelib/fastapi/monitoring.py @@ -3,6 +3,7 @@ import asyncio import logging from collections.abc import AsyncIterator +from time import perf_counter from typing import Final from fastapi import FastAPI, Request, Response, status @@ -39,10 +40,12 @@ async def dispatch( self, request: Request, call_next: RequestResponseEndpoint ) -> Response: canonical_endpoint = request.url.path + user_agent = request.headers.get( X_SIMCORE_USER_AGENT, UNDEFINED_DEFAULT_SIMCORE_USER_AGENT_VALUE ) + start_time = perf_counter() try: with record_request_metrics( metrics=self.metrics, @@ -52,18 +55,26 @@ async def dispatch( ): response = await call_next(request) status_code = response.status_code + + # path_params are not available before calling call_next + # https://github.com/encode/starlette/issues/685#issuecomment-550240999 + for k, v in request.path_params.items(): + key = "{" + k + "}" + canonical_endpoint = canonical_endpoint.replace(f"/{v}", f"/{key}") except Exception: # pylint: disable=broad-except # NOTE: The prometheus metrics middleware should be "outside" exception handling # middleware. See https://fastapi.tiangolo.com/advanced/middleware/#adding-asgi-middlewares status_code = status.HTTP_500_INTERNAL_SERVER_ERROR raise finally: + reponse_latency_seconds = perf_counter() - start_time record_response_metrics( metrics=self.metrics, method=request.method, endpoint=canonical_endpoint, user_agent=user_agent, http_status=status_code, + response_latency_seconds=reponse_latency_seconds, ) return response diff --git a/packages/service-library/src/servicelib/prometheus_metrics.py b/packages/service-library/src/servicelib/prometheus_metrics.py index 0ee74115b8e..b4915ff365b 100644 --- a/packages/service-library/src/servicelib/prometheus_metrics.py +++ b/packages/service-library/src/servicelib/prometheus_metrics.py @@ -1,7 +1,6 @@ from collections.abc import Iterator from contextlib import contextmanager from dataclasses import dataclass -from time import perf_counter from opentelemetry import trace from prometheus_client import ( @@ -132,20 +131,8 @@ def record_request_metrics( with metrics.in_flight_requests.labels( method, endpoint, user_agent ).track_inprogress(): - - start = perf_counter() - yield - amount = perf_counter() - start - exemplar = _get_exemplar() - metrics.response_latency_with_labels.labels( - method, endpoint, user_agent - ).observe(amount=amount, exemplar=exemplar) - metrics.response_latency_detailed_buckets.observe( - amount=amount, exemplar=exemplar - ) - def record_response_metrics( *, @@ -154,8 +141,15 @@ def record_response_metrics( endpoint: str, user_agent: str, http_status: int, + response_latency_seconds: float, ) -> None: exemplar = _get_exemplar() metrics.request_count.labels(method, endpoint, http_status, user_agent).inc( exemplar=exemplar ) + metrics.response_latency_with_labels.labels(method, endpoint, user_agent).observe( + amount=response_latency_seconds, exemplar=exemplar + ) + metrics.response_latency_detailed_buckets.observe( + amount=response_latency_seconds, exemplar=exemplar + )