Avoid fetching loop time on each request unless logging is enabled

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

@@ -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.
 

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

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()