Add object source logger to profiler

homeassistant/components/profiler/__init__.py

@@ -17,7 +17,7 @@
 from homeassistant.components import persistent_notification
 from homeassistant.config_entries import ConfigEntry
 from homeassistant.const import CONF_SCAN_INTERVAL, CONF_TYPE
-from homeassistant.core import HomeAssistant, ServiceCall
+from homeassistant.core import HomeAssistant, ServiceCall, callback
 from homeassistant.exceptions import HomeAssistantError
 import homeassistant.helpers.config_validation as cv
 from homeassistant.helpers.event import async_track_time_interval
@@ -29,6 +29,8 @@
 SERVICE_MEMORY = "memory"
 SERVICE_START_LOG_OBJECTS = "start_log_objects"
 SERVICE_STOP_LOG_OBJECTS = "stop_log_objects"
+SERVICE_START_LOG_OBJECT_SOURCES = "start_log_object_sources"
+SERVICE_STOP_LOG_OBJECT_SOURCES = "stop_log_object_sources"
 SERVICE_DUMP_LOG_OBJECTS = "dump_log_objects"
 SERVICE_LRU_STATS = "lru_stats"
 SERVICE_LOG_THREAD_FRAMES = "log_thread_frames"
@@ -60,7 +62,10 @@
 
 DEFAULT_SCAN_INTERVAL = timedelta(seconds=30)
 
+DEFAULT_MAX_OBJECTS = 5
+
 CONF_SECONDS = "seconds"
+CONF_MAX_OBJECTS = "max_objects"
 
 LOG_INTERVAL_SUB = "log_interval_subscription"
 
@@ -85,7 +90,7 @@ async def _async_run_memory_profile(call: ServiceCall) -> None:
 
     async def _async_start_log_objects(call: ServiceCall) -> None:
         if LOG_INTERVAL_SUB in domain_data:
-            domain_data[LOG_INTERVAL_SUB]()
+            raise HomeAssistantError("Object logging already started")
 
         persistent_notification.async_create(
             hass,
@@ -103,21 +108,53 @@ async def _async_start_log_objects(call: ServiceCall) -> None:
 
     async def _async_stop_log_objects(call: ServiceCall) -> None:
         if LOG_INTERVAL_SUB not in domain_data:
-            return
+            raise HomeAssistantError("Object logging not running")
 
         persistent_notification.async_dismiss(hass, "profile_object_logging")
         domain_data.pop(LOG_INTERVAL_SUB)()
 
-    def _safe_repr(obj: Any) -> str:
-        """Get the repr of an object but keep going if there is an exception.
+    async def _async_start_object_sources(call: ServiceCall) -> None:
+        if LOG_INTERVAL_SUB in domain_data:
+            raise HomeAssistantError("Object logging already started")
 
-        We wrap repr to ensure if one object cannot be serialized, we can
-        still get the rest.
-        """
-        try:
-            return repr(obj)
-        except Exception:  # pylint: disable=broad-except
-            return f"Failed to serialize {type(obj)}"
+        persistent_notification.async_create(
+            hass,
+            (
+                "Object source logging has started. See [the logs](/config/logs) to"
+                " track the growth of new objects."
+            ),
+            title="Object source logging started",
+            notification_id="profile_object_source_logging",
+        )
+
+        last_ids: set[int] = set()
+        last_stats: dict[str, int] = {}
+
+        async def _log_object_sources_with_max(*_: Any) -> None:
+            await hass.async_add_executor_job(
+                _log_object_sources, call.data[CONF_MAX_OBJECTS], last_ids, last_stats
+            )
+
+        await _log_object_sources_with_max()
+        cancel_track = async_track_time_interval(
+            hass, _log_object_sources_with_max, call.data[CONF_SCAN_INTERVAL]
+        )
+
+        @callback
+        def _cancel():
+            cancel_track()
+            last_ids.clear()
+            last_stats.clear()
+
+        domain_data[LOG_INTERVAL_SUB] = _cancel
+
+    @callback
+    def _async_stop_object_sources(call: ServiceCall) -> None:
+        if LOG_INTERVAL_SUB not in domain_data:
+            raise HomeAssistantError("Object logging not running")
+
+        persistent_notification.async_dismiss(hass, "profile_object_source_logging")
+        domain_data.pop(LOG_INTERVAL_SUB)()
 
     def _dump_log_objects(call: ServiceCall) -> None:
         # Imports deferred to avoid loading modules
@@ -143,15 +180,6 @@ def _dump_log_objects(call: ServiceCall) -> None:
             notification_id="profile_object_dump",
         )
 
-    def _get_function_absfile(func: Any) -> str:
-        """Get the absolute file path of a function."""
-        import inspect  # pylint: disable=import-outside-toplevel
-
-        abs_file = "unknown"
-        with suppress(Exception):
-            abs_file = inspect.getabsfile(func)
-        return abs_file
-
     def _lru_stats(call: ServiceCall) -> None:
         """Log the stats of all lru caches."""
         # Imports deferred to avoid loading modules
@@ -164,7 +192,7 @@ def _lru_stats(call: ServiceCall) -> None:
             _LOGGER.critical(
                 "Cache stats for lru_cache %s at %s: %s",
                 lru.__wrapped__,
-                _get_function_absfile(lru.__wrapped__),
+                _get_function_absfile(lru.__wrapped__) or "unknown",
                 lru.cache_info(),
             )
 
@@ -175,7 +203,7 @@ def _lru_stats(call: ServiceCall) -> None:
                         _LOGGER.critical(
                             "Cache stats for LRU %s at %s: %s",
                             type(class_with_lru_attr),
-                            _get_function_absfile(class_with_lru_attr),
+                            _get_function_absfile(class_with_lru_attr) or "unknown",
                             maybe_lru.get_stats(),
                         )
 
@@ -267,6 +295,30 @@ async def _async_dump_scheduled(call: ServiceCall) -> None:
         _async_stop_log_objects,
     )
 
+    async_register_admin_service(
+        hass,
+        DOMAIN,
+        SERVICE_START_LOG_OBJECT_SOURCES,
+        _async_start_object_sources,
+        schema=vol.Schema(
+            {
+                vol.Optional(
+                    CONF_SCAN_INTERVAL, default=DEFAULT_SCAN_INTERVAL
+                ): cv.time_period,
+                vol.Optional(CONF_MAX_OBJECTS, default=DEFAULT_MAX_OBJECTS): vol.Range(
+                    min=1, max=1024
+                ),
+            }
+        ),
+    )
+
+    async_register_admin_service(
+        hass,
+        DOMAIN,
+        SERVICE_STOP_LOG_OBJECT_SOURCES,
+        _async_stop_object_sources,
+    )
+
     async_register_admin_service(
         hass,
         DOMAIN,
@@ -404,3 +456,101 @@ def _log_objects(*_):
     import objgraph  # pylint: disable=import-outside-toplevel
 
     _LOGGER.critical("Memory Growth: %s", objgraph.growth(limit=1000))
+
+
+def _get_function_absfile(func: Any) -> str | None:
+    """Get the absolute file path of a function."""
+    import inspect  # pylint: disable=import-outside-toplevel
+
+    abs_file: str | None = None
+    with suppress(Exception):
+        abs_file = inspect.getabsfile(func)
+    return abs_file
+
+
+def _safe_repr(obj: Any) -> str:
+    """Get the repr of an object but keep going if there is an exception.
+
+    We wrap repr to ensure if one object cannot be serialized, we can
+    still get the rest.
+    """
+    try:
+        return repr(obj)
+    except Exception:  # pylint: disable=broad-except
+        return f"Failed to serialize {type(obj)}"
+
+
+def _find_backrefs_not_to_self(_object: Any) -> list[str]:
+    import objgraph  # pylint: disable=import-outside-toplevel
+
+    return [
+        _safe_repr(backref)
+        for backref in objgraph.find_backref_chain(
+            _object, lambda obj: obj is not _object
+        )
+    ]
+
+
+def _log_object_sources(
+    max_objects: int, last_ids: set[int], last_stats: dict[str, int]
+) -> None:
+    # Imports deferred to avoid loading modules
+    # in memory since usually only one part of this
+    # integration is used at a time
+    import gc  # pylint: disable=import-outside-toplevel
+
+    gc.collect()
+
+    objects = gc.get_objects()
+    new_objects: list[object] = []
+    new_objects_overflow: dict[str, int] = {}
+    current_ids = set()
+    new_stats: dict[str, int] = {}
+    had_new_object_growth = False
+    try:
+        for _object in objects:
+            object_type = type(_object).__name__
+            new_stats[object_type] = new_stats.get(object_type, 0) + 1
+
+        for _object in objects:
+            id_ = id(_object)
+            current_ids.add(id_)
+            if id_ in last_ids:
+                continue
+            object_type = type(_object).__name__
+            if last_stats.get(object_type, 0) < new_stats[object_type]:
+                if len(new_objects) < max_objects:
+                    new_objects.append(_object)
+                else:
+                    new_objects_overflow.setdefault(object_type, 0)
+                    new_objects_overflow[object_type] += 1
+
+        for _object in new_objects:
+            had_new_object_growth = True
+            object_type = type(_object).__name__
+            _LOGGER.critical(
+                "New object %s (%s/%s) at %s: %s",
+                object_type,
+                last_stats.get(object_type, 0),
+                new_stats[object_type],
+                _get_function_absfile(_object) or _find_backrefs_not_to_self(_object),
+                _safe_repr(_object),
+            )
+
+        for object_type, count in last_stats.items():
+            new_stats[object_type] = max(new_stats.get(object_type, 0), count)
+    finally:
+        # Break reference cycles
+        del objects
+        del new_objects
+        last_ids.clear()
+        last_ids.update(current_ids)
+        last_stats.clear()
+        last_stats.update(new_stats)
+        del new_stats
+        del current_ids
+
+    if new_objects_overflow:
+        _LOGGER.critical("New objects overflowed by %s", new_objects_overflow)
+    elif not had_new_object_growth:
+        _LOGGER.critical("No new object growth found")

homeassistant/components/profiler/services.yaml

@@ -25,7 +25,7 @@ memory:
           max: 3600
           unit_of_measurement: seconds
 start_log_objects:
-  name: Start log objects
+  name: Start logging objects
   description: Start logging growth of objects in memory
   fields:
     scan_interval:
@@ -38,7 +38,7 @@ start_log_objects:
           max: 3600
           unit_of_measurement: seconds
 stop_log_objects:
-  name: Stop log objects
+  name: Stop logging objects
   description: Stop logging growth of objects in memory.
 dump_log_objects:
   name: Dump log objects
@@ -51,6 +51,31 @@ dump_log_objects:
       example: State
       selector:
         text:
+start_log_object_sources:
+  name: Start logging object sources
+  description: Start logging sources of new objects in memory
+  fields:
+    scan_interval:
+      name: Scan interval
+      description: The number of seconds between logging objects.
+      default: 30.0
+      selector:
+        number:
+          min: 1
+          max: 3600
+          unit_of_measurement: seconds
+    max_objects:
+      name: Maximum objects
+      description: The maximum number of objects to log.
+      default: 5
+      selector:
+        number:
+          min: 1
+          max: 30
+          unit_of_measurement: objects
+stop_log_object_sources:
+  name: Stop logging object sources
+  description: Stop logging sources of new objects in memory.
 lru_stats:
   name: Log LRU stats
   description: Log the stats of all lru caches.