Significantly improve logging performance when no integrations are requesting debug level (#37776)

homeassistant/components/logger/__init__.py

@@ -13,6 +13,8 @@ DATA_LOGGER = "logger"
 SERVICE_SET_DEFAULT_LEVEL = "set_default_level"
 SERVICE_SET_LEVEL = "set_level"
 
+HIGHEST_LOG_LEVEL = logging.CRITICAL
+
 LOGSEVERITY = {
     "CRITICAL": 50,
     "FATAL": 50,
@@ -55,7 +57,7 @@ class HomeAssistantLogFilter(logging.Filter):
         super().__init__()
 
         self._default = None
-        self._logs = None
+        self._logs = {}
         self._log_rx = None
 
     def update_default_level(self, default_level):
@@ -77,6 +79,23 @@ class HomeAssistantLogFilter(logging.Filter):
         self._log_rx = re.compile("".join(["^(?:", "|".join(names_by_len), ")"]))
         self._logs = logs
 
+    def set_logger_level(self):
+        """Find the lowest log level set to allow logger to pre-filter log messages."""
+        #
+        # We set the root logger level to lowest log level
+        # specified in default or for in the log filter so
+        # logger.isEnabledFor function will work as designed
+        # to avoid making logger records that will always be
+        # discarded.
+        #
+        # This can make the logger performance significantly
+        # faster if no integrations are requesting debug logs
+        # because we can avoid the record creation and filtering
+        # overhead.
+        #
+        logger = logging.getLogger("")
+        logger.setLevel(min(HIGHEST_LOG_LEVEL, self._default, *self._logs.values()))
+
     def filter(self, record):
         """Filter the log entries."""
         # Log with filtered severity
@@ -121,9 +140,6 @@ async def async_setup(hass, config):
     else:
         set_default_log_level("DEBUG")
 
-    logger = logging.getLogger("")
-    logger.setLevel(logging.NOTSET)
-
     # Set log filter for all log handler
     for handler in logging.root.handlers:
         handler.setLevel(logging.NOTSET)
@@ -132,12 +148,15 @@ async def async_setup(hass, config):
     if LOGGER_LOGS in config.get(DOMAIN):
         set_log_levels(config.get(DOMAIN)[LOGGER_LOGS])
 
+    hass_filter.set_logger_level()
+
     async def async_service_handler(service):
         """Handle logger services."""
         if service.service == SERVICE_SET_DEFAULT_LEVEL:
             set_default_log_level(service.data.get(ATTR_LEVEL))
         else:
             set_log_levels(service.data)
+        hass_filter.set_logger_level()
 
     hass.services.async_register(
         DOMAIN,

tests/components/logger/test_init.py

@@ -37,6 +37,8 @@ async def test_logger_test_filters(hass):
     """Test resulting filter operation."""
     log_filter = await async_setup_logger(hass, TEST_CONFIG)
 
+    assert logging.getLogger("").isEnabledFor(logging.DEBUG) is True
+
     # Blocked default record
     assert not log_filter.filter(RECORD("asdf", logging.DEBUG))
 
@@ -66,13 +68,27 @@ async def test_set_filter_empty_config(hass):
     """Test change log level from empty configuration."""
     log_filter = await async_setup_logger(hass, NO_LOGS_CONFIG)
 
+    assert logging.getLogger("").isEnabledFor(logging.DEBUG) is False
+
     assert not log_filter.filter(RECORD("test", logging.DEBUG))
 
+    await hass.services.async_call(
+        logger.DOMAIN, "set_default_level", {"level": "warning"}
+    )
+    await hass.async_block_till_done()
+
+    assert not log_filter.filter(RECORD("test", logging.DEBUG))
+
+    assert logging.getLogger("").isEnabledFor(logging.DEBUG) is False
+    assert logging.getLogger("").isEnabledFor(logging.WARNING) is True
+
     await hass.services.async_call(logger.DOMAIN, "set_level", {"test": "debug"})
     await hass.async_block_till_done()
 
     assert log_filter.filter(RECORD("test", logging.DEBUG))
 
+    assert logging.getLogger("").isEnabledFor(logging.DEBUG) is True
+
 
 async def test_set_filter(hass):
     """Test change log level of existing filter."""
@@ -94,6 +110,9 @@ async def test_set_default_filter_empty_config(hass):
     """Test change default log level from empty configuration."""
     log_filter = await async_setup_logger(hass, NO_DEFAULT_CONFIG)
 
+    assert logging.getLogger("").isEnabledFor(logging.DEBUG) is True
+    assert logging.getLogger("").isEnabledFor(logging.WARNING) is True
+
     assert log_filter.filter(RECORD("test", logging.DEBUG))
 
     await hass.services.async_call(
@@ -103,6 +122,10 @@ async def test_set_default_filter_empty_config(hass):
 
     assert not log_filter.filter(RECORD("test", logging.DEBUG))
 
+    assert logging.getLogger("").isEnabledFor(logging.DEBUG) is False
+    assert logging.getLogger("").isEnabledFor(logging.INFO) is False
+    assert logging.getLogger("").isEnabledFor(logging.WARNING) is True
+
 
 async def test_set_default_filter(hass):
     """Test change default log level with existing default."""