[PR #10713/8d74e26 backport][3.11] Avoid fetching loop time on each request unless logging is enabled (#10738)

Co-authored-by: Sam Bull <[email protected]>

Author: bdraco

CHANGES/10713.misc.rst

@@ -0,0 +1 @@
+Optimized web server performance when access logging is disabled by reducing time syscalls -- by :user:`bdraco`.

aiohttp/web_protocol.py

@@ -170,6 +170,7 @@ class RequestHandler(BaseProtocol):
         "_current_request",
         "_timeout_ceil_threshold",
         "_request_in_progress",
+        "_logging_enabled",
         "_cache",
     )
 
@@ -244,8 +245,10 @@ def __init__(
             self.access_logger: Optional[AbstractAccessLogger] = access_log_class(
                 access_log, access_log_format
             )
+            self._logging_enabled = self.access_logger.enabled
         else:
             self.access_logger = None
+            self._logging_enabled = False
 
         self._close = False
         self._force_close = False
@@ -463,9 +466,11 @@ def force_close(self) -> None:
             self.transport = None
 
     def log_access(
-        self, request: BaseRequest, response: StreamResponse, time: float
+        self, request: BaseRequest, response: StreamResponse, time: Optional[float]
     ) -> None:
         if self.access_logger is not None and self.access_logger.enabled:
+            if TYPE_CHECKING:
+                assert time is not None
             self.access_logger.log(request, response, self._loop.time() - time)
 
     def log_debug(self, *args: Any, **kw: Any) -> None:
@@ -495,7 +500,7 @@ def _process_keepalive(self) -> None:
     async def _handle_request(
         self,
         request: BaseRequest,
-        start_time: float,
+        start_time: Optional[float],
         request_handler: Callable[[BaseRequest], Awaitable[StreamResponse]],
     ) -> Tuple[StreamResponse, bool]:
         self._request_in_progress = True
@@ -563,7 +568,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)
@@ -671,7 +678,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.
 

tests/test_web_app.py

@@ -144,6 +144,20 @@ def log(self, request, response, time):
     )
 
 
+async def test_app_make_handler_no_access_log_class(mocker) -> None:
+    srv = mocker.patch("aiohttp.web_app.Server")
+    app = web.Application(handler_args={"access_log": None})
+    app._make_handler(access_log=None)
+    srv.assert_called_with(
+        app._handle,
+        request_factory=app._make_request,
+        loop=asyncio.get_event_loop(),
+        access_log=None,
+        debug=mock.ANY,
+        access_log_class=mock.ANY,
+    )
+
+
 async def test_app_make_handler_raises_deprecation_warning() -> None:
     app = web.Application()
 

tests/test_web_log.py

@@ -255,3 +255,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