Improve performance of the access logger when its disabled (#9822)

CHANGES/9822.feature.rst

@@ -0,0 +1 @@
+Added an :attr:`~aiohttp.abc.AbstractAccessLogger.enabled` property to :class:`aiohttp.abc.AbstractAccessLogger` to dynamically check if logging is enabled -- by :user:`bdraco`.

aiohttp/abc.py

@@ -227,6 +227,8 @@ async def write_headers(
 class AbstractAccessLogger(ABC):
     """Abstract writer to access log."""
 
+    __slots__ = ("logger", "log_format")
+
     def __init__(self, logger: logging.Logger, log_format: str) -> None:
         self.logger = logger
         self.log_format = log_format
@@ -235,12 +237,24 @@ def __init__(self, logger: logging.Logger, log_format: str) -> None:
     def log(self, request: BaseRequest, response: StreamResponse, time: float) -> None:
         """Emit log to logger."""
 
+    @property
+    def enabled(self) -> bool:
+        """Check if logger is enabled."""
+        return True
+
 
 class AbstractAsyncAccessLogger(ABC):
     """Abstract asynchronous writer to access log."""
 
+    __slots__ = ()
+
     @abstractmethod
     async def log(
         self, request: BaseRequest, response: StreamResponse, request_start: float
     ) -> None:
         """Emit log to logger."""
+
+    @property
+    def enabled(self) -> bool:
+        """Check if logger is enabled."""
+        return True

aiohttp/web_log.py

@@ -181,10 +181,13 @@ def _format_line(
     ) -> Iterable[Tuple[str, Callable[[BaseRequest, StreamResponse, float], str]]]:
         return [(key, method(request, response, time)) for key, method in self._methods]
 
+    @property
+    def enabled(self) -> bool:
+        """Check if logger is enabled."""
+        # Avoid formatting the log line if it will not be emitted.
+        return self.logger.isEnabledFor(logging.INFO)
+
     def log(self, request: BaseRequest, response: StreamResponse, time: float) -> None:
-        if not self.logger.isEnabledFor(logging.INFO):
-            # Avoid formatting the log line if it will not be emitted.
-            return
         try:
             fmt_info = self._format_line(request, response, time)
 

aiohttp/web_protocol.py

@@ -96,6 +96,8 @@ class PayloadAccessError(Exception):
 class AccessLoggerWrapper(AbstractAsyncAccessLogger):
     """Wrap an AbstractAccessLogger so it behaves like an AbstractAsyncAccessLogger."""
 
+    __slots__ = ("access_logger", "_loop")
+
     def __init__(
         self, access_logger: AbstractAccessLogger, loop: asyncio.AbstractEventLoop
     ) -> None:
@@ -108,6 +110,11 @@ async def log(
     ) -> None:
         self.access_logger.log(request, response, self._loop.time() - request_start)
 
+    @property
+    def enabled(self) -> bool:
+        """Check if logger is enabled."""
+        return self.access_logger.enabled
+
 
 @dataclasses.dataclass(frozen=True)
 class _ErrInfo:
@@ -461,7 +468,7 @@ def force_close(self) -> None:
     async def log_access(
         self, request: BaseRequest, response: StreamResponse, request_start: float
     ) -> None:
-        if self.access_logger is not None:
+        if self.access_logger is not None and self.access_logger.enabled:
             await self.access_logger.log(request, response, request_start)
 
     def log_debug(self, *args: Any, **kw: Any) -> None:

docs/abc.rst

@@ -182,6 +182,15 @@ Abstract Access Logger
 
       :param float time: Time taken to serve the request.
 
+   .. attribute:: enabled
+
+        Return True if logger is enabled.
+
+        Override this property if logging is disabled to avoid the
+        overhead of calculating details to feed the logger.
+
+        This property may be omitted if logging is always enabled.
+
 
 Abstract Resolver
 -------------------------------

docs/logging.rst

@@ -114,6 +114,16 @@ Example of a drop-in replacement for the default access logger::
                            f'"{request.method} {request.path} '
                            f'done in {time}s: {response.status}')
 
+      @property
+      def enabled(self):
+          """Return True if logger is enabled.
+
+          Override this property if logging is disabled to avoid the
+          overhead of calculating details to feed the logger.
+
+          This property may be omitted if logging is always enabled.
+          """
+          return self.logger.isEnabledFor(logging.INFO)
 
 .. versionadded:: 4.0.0
 
@@ -139,6 +149,15 @@ If your logging needs to perform IO you can instead inherit from
                                     f'"{request.method} {request.path} '
                                     f'done in {time}s: {response.status}')
 
+      @property
+      def enabled(self) -> bool:
+          """Return True if logger is enabled.
+
+          Override this property if logging is disabled to avoid the
+          overhead of calculating details to feed the logger.
+          """
+          return self.logger.isEnabledFor(logging.INFO)
+
 
 This also allows access to the results of coroutines on the ``request`` and
 ``response``, e.g. ``request.text()``.

tests/test_web_log.py

@@ -275,12 +275,42 @@ def log(
     assert msg == "contextvars: uuid"
 
 
-def test_logger_does_nothing_when_disabled(caplog: pytest.LogCaptureFixture) -> None:
-    """Test that the logger does nothing when the log level is disabled."""
+def test_access_logger_feeds_logger(caplog: pytest.LogCaptureFixture) -> None:
+    """Test that the logger still works."""
     mock_logger = logging.getLogger("test.aiohttp.log")
     mock_logger.setLevel(logging.INFO)
     access_logger = AccessLogger(mock_logger, "%b")
     access_logger.log(
         mock.Mock(name="mock_request"), mock.Mock(name="mock_response"), 42
     )
     assert "mock_response" in caplog.text
+
+
+async def test_logger_does_not_log_when_not_enabled(
+    aiohttp_server: AiohttpServer,
+    aiohttp_client: AiohttpClient,
+    caplog: pytest.LogCaptureFixture,
+) -> None:
+    """Test logger does nothing when not enabled."""
+
+    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
+
+        @property
+        def enabled(self) -> bool:
+            return False
+
+    app = web.Application()
+    app.router.add_get("/", handler)
+    server = await aiohttp_server(app, 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