From 8d74e26c70adeabda54c963d4744672c1874cb06 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Fri, 18 Apr 2025 08:09:14 -1000 Subject: [PATCH] Avoid fetching loop time on each request unless logging is enabled (#10713) Co-authored-by: Sam Bull --- CHANGES/10713.misc.rst | 1 + aiohttp/web_protocol.py | 20 +++++++++++++++----- tests/test_web_log.py | 26 ++++++++++++++++++++++++++ tests/test_web_runner.py | 6 ++++++ 4 files changed, 48 insertions(+), 5 deletions(-) create mode 100644 CHANGES/10713.misc.rst diff --git a/CHANGES/10713.misc.rst b/CHANGES/10713.misc.rst new file mode 100644 index 00000000000..a556d11e1e0 --- /dev/null +++ b/CHANGES/10713.misc.rst @@ -0,0 +1 @@ +Optimized web server performance when access logging is disabled by reducing time syscalls -- by :user:`bdraco`. diff --git a/aiohttp/web_protocol.py b/aiohttp/web_protocol.py index 38d49ceeb30..cdeb423554f 100644 --- a/aiohttp/web_protocol.py +++ b/aiohttp/web_protocol.py @@ -192,6 +192,7 @@ class RequestHandler(BaseProtocol, Generic[_Request]): "_current_request", "_timeout_ceil_threshold", "_request_in_progress", + "_logging_enabled", "_cache", ) @@ -273,8 +274,10 @@ def __init__( access_logger, self._loop, ) + self._logging_enabled = self.access_logger.enabled else: self.access_logger = None + self._logging_enabled = False self._close = False self._force_close = False @@ -492,9 +495,14 @@ def force_close(self) -> None: self.transport = None async def log_access( - self, request: BaseRequest, response: StreamResponse, request_start: float + self, + request: BaseRequest, + response: StreamResponse, + request_start: Optional[float], ) -> None: - if self.access_logger is not None and self.access_logger.enabled: + if self._logging_enabled and self.access_logger is not None: + if TYPE_CHECKING: + assert request_start is not None await self.access_logger.log(request, response, request_start) def log_debug(self, *args: Any, **kw: Any) -> None: @@ -524,7 +532,7 @@ def _process_keepalive(self) -> None: async def _handle_request( self, request: _Request, - start_time: float, + start_time: Optional[float], request_handler: Callable[[_Request], Awaitable[StreamResponse]], ) -> Tuple[StreamResponse, bool]: self._request_in_progress = True @@ -586,7 +594,9 @@ async def start(self) -> None: message, payload = self._messages.popleft() - start = loop.time() + # time is only fetched if logging is enabled as otherwise + # its thrown away and never used. + start = loop.time() if self._logging_enabled else None manager.requests_count += 1 writer = StreamWriter(self, loop) @@ -696,7 +706,7 @@ async def start(self) -> None: self.transport.close() async def finish_response( - self, request: BaseRequest, resp: StreamResponse, start_time: float + self, request: BaseRequest, resp: StreamResponse, start_time: Optional[float] ) -> Tuple[StreamResponse, bool]: """Prepare the response and write_eof, then log access. diff --git a/tests/test_web_log.py b/tests/test_web_log.py index ffd2959039f..6456735de4a 100644 --- a/tests/test_web_log.py +++ b/tests/test_web_log.py @@ -314,3 +314,29 @@ def enabled(self) -> bool: resp = await client.get("/") assert 200 == resp.status assert "This should not be logged" not in caplog.text + + +async def test_logger_set_to_none( + aiohttp_server: AiohttpServer, + aiohttp_client: AiohttpClient, + caplog: pytest.LogCaptureFixture, +) -> None: + """Test logger does nothing when access_log is set to None.""" + + async def handler(request: web.Request) -> web.Response: + return web.Response() + + class Logger(AbstractAccessLogger): + + def log( + self, request: web.BaseRequest, response: web.StreamResponse, time: float + ) -> None: + self.logger.critical("This should not be logged") # pragma: no cover + + app = web.Application() + app.router.add_get("/", handler) + server = await aiohttp_server(app, access_log=None, access_log_class=Logger) + client = await aiohttp_client(server) + resp = await client.get("/") + assert 200 == resp.status + assert "This should not be logged" not in caplog.text diff --git a/tests/test_web_runner.py b/tests/test_web_runner.py index d75e68ee153..8da4867372a 100644 --- a/tests/test_web_runner.py +++ b/tests/test_web_runner.py @@ -196,6 +196,12 @@ def log( assert runner._kwargs["access_log_class"] is Logger +async def test_app_make_handler_no_access_log_class() -> None: + app = web.Application(handler_args={"access_log": None}) + runner = web.AppRunner(app) + assert runner._kwargs["access_log"] is None + + async def test_addresses(make_runner: _RunnerMaker, unix_sockname: str) -> None: _sock = get_unused_port_socket("127.0.0.1") runner = make_runner()