Add services to log and dump objects to the profiler to help track down memory leaks (#42951)

Co-authored-by: Paulus Schoutsen <paulus@home-assistant.io>

homeassistant/components/profiler/__init__.py

@@ -1,14 +1,19 @@
 """The profiler integration."""
 import asyncio
 import cProfile
+from datetime import timedelta
+import logging
 import time
 
 from guppy import hpy
+import objgraph
 from pyprof2calltree import convert
 import voluptuous as vol
 
 from homeassistant.config_entries import ConfigEntry
 from homeassistant.core import HomeAssistant, ServiceCall
+import homeassistant.helpers.config_validation as cv
+from homeassistant.helpers.event import async_track_time_interval
 from homeassistant.helpers.service import async_register_admin_service
 from homeassistant.helpers.typing import ConfigType
 
@@ -16,7 +21,27 @@ from .const import DOMAIN
 
 SERVICE_START = "start"
 SERVICE_MEMORY = "memory"
+SERVICE_START_LOG_OBJECTS = "start_log_objects"
+SERVICE_STOP_LOG_OBJECTS = "stop_log_objects"
+SERVICE_DUMP_LOG_OBJECTS = "dump_log_objects"
+
+SERVICES = (
+    SERVICE_START,
+    SERVICE_MEMORY,
+    SERVICE_START_LOG_OBJECTS,
+    SERVICE_STOP_LOG_OBJECTS,
+    SERVICE_DUMP_LOG_OBJECTS,
+)
+
+DEFAULT_SCAN_INTERVAL = timedelta(seconds=30)
+
 CONF_SECONDS = "seconds"
+CONF_SCAN_INTERVAL = "scan_interval"
+CONF_TYPE = "type"
+
+LOG_INTERVAL_SUB = "log_interval_subscription"
+
+_LOGGER = logging.getLogger(__name__)
 
 
 async def async_setup(hass: HomeAssistant, config: ConfigType) -> bool:
@@ -28,6 +53,7 @@ async def async_setup_entry(hass: HomeAssistant, entry: ConfigEntry):
     """Set up Profiler from a config entry."""
 
     lock = asyncio.Lock()
+    domain_data = hass.data[DOMAIN] = {}
 
     async def _async_run_profile(call: ServiceCall):
         async with lock:
@@ -37,6 +63,42 @@ async def async_setup_entry(hass: HomeAssistant, entry: ConfigEntry):
         async with lock:
             await _async_generate_memory_profile(hass, call)
 
+    async def _async_start_log_objects(call: ServiceCall):
+        if LOG_INTERVAL_SUB in domain_data:
+            domain_data[LOG_INTERVAL_SUB]()
+
+        hass.components.persistent_notification.async_create(
+            "Object growth logging has started. See [the logs](/config/logs) to track the growth of new objects.",
+            title="Object growth logging started",
+            notification_id="profile_object_logging",
+        )
+        await hass.async_add_executor_job(_log_objects)
+        domain_data[LOG_INTERVAL_SUB] = async_track_time_interval(
+            hass, _log_objects, call.data[CONF_SCAN_INTERVAL]
+        )
+
+    async def _async_stop_log_objects(call: ServiceCall):
+        if LOG_INTERVAL_SUB not in domain_data:
+            return
+
+        hass.components.persistent_notification.async_dismiss("profile_object_logging")
+        domain_data.pop(LOG_INTERVAL_SUB)()
+
+    def _dump_log_objects(call: ServiceCall):
+        obj_type = call.data[CONF_TYPE]
+
+        _LOGGER.critical(
+            "%s objects in memory: %s",
+            obj_type,
+            objgraph.by_type(obj_type),
+        )
+
+        hass.components.persistent_notification.create(
+            f"Objects with type {obj_type} have been dumped to the log. See [the logs](/config/logs) to review the repr of the objects.",
+            title="Object dump completed",
+            notification_id="profile_object_dump",
+        )
+
     async_register_admin_service(
         hass,
         DOMAIN,
@@ -57,12 +119,46 @@ async def async_setup_entry(hass: HomeAssistant, entry: ConfigEntry):
         ),
     )
 
+    async_register_admin_service(
+        hass,
+        DOMAIN,
+        SERVICE_START_LOG_OBJECTS,
+        _async_start_log_objects,
+        schema=vol.Schema(
+            {
+                vol.Optional(
+                    CONF_SCAN_INTERVAL, default=DEFAULT_SCAN_INTERVAL
+                ): cv.time_period
+            }
+        ),
+    )
+
+    async_register_admin_service(
+        hass,
+        DOMAIN,
+        SERVICE_STOP_LOG_OBJECTS,
+        _async_stop_log_objects,
+        schema=vol.Schema({}),
+    )
+
+    async_register_admin_service(
+        hass,
+        DOMAIN,
+        SERVICE_DUMP_LOG_OBJECTS,
+        _dump_log_objects,
+        schema=vol.Schema({vol.Required(CONF_TYPE): str}),
+    )
+
     return True
 
 
 async def async_unload_entry(hass: HomeAssistant, entry: ConfigEntry):
     """Unload a config entry."""
-    hass.services.async_remove(domain=DOMAIN, service=SERVICE_START)
+    for service in SERVICES:
+        hass.services.async_remove(domain=DOMAIN, service=service)
+    if LOG_INTERVAL_SUB in hass.data[DOMAIN]:
+        hass.data[DOMAIN][LOG_INTERVAL_SUB]()
+    hass.data.pop(DOMAIN)
     return True
 
 
@@ -119,3 +215,7 @@ def _write_profile(profiler, cprofile_path, callgrind_path):
 
 def _write_memory_profile(heap, heap_path):
     heap.byrcs.dump(heap_path)
+
+
+def _log_objects(*_):
+    _LOGGER.critical("Memory Growth: %s", objgraph.growth(limit=100))

homeassistant/components/profiler/manifest.json

@@ -2,7 +2,7 @@
   "domain": "profiler",
   "name": "Profiler",
   "documentation": "https://www.home-assistant.io/integrations/profiler",
-  "requirements": ["pyprof2calltree==1.4.5", "guppy3==3.1.0"],
+  "requirements": ["pyprof2calltree==1.4.5", "guppy3==3.1.0", "objgraph==3.4.1"],
   "codeowners": ["@bdraco"],
   "quality_scale": "internal",
   "config_flow": true

homeassistant/components/profiler/services.yaml

@@ -10,3 +10,17 @@ memory:
     seconds:
       description: The number of seconds to run the memory profiler.
       example: 60.0
+start_log_objects:
+  description: Start logging growth of objects in memory
+  fields:
+    scan_interval:
+      description: The number of seconds between logging objects.
+      example: 60.0
+stop_log_objects:
+  description: Stop logging growth of objects in memory
+dump_log_objects:
+  description: Dump the repr of all matching objects to the log.
+  fields:
+    type:
+      description: The type of objects to dump to the log
+      example: State

requirements_all.txt

@@ -1024,6 +1024,9 @@ oasatelematics==0.3
 # homeassistant.components.google
 oauth2client==4.0.0
 
+# homeassistant.components.profiler
+objgraph==3.4.1
+
 # homeassistant.components.oem
 oemthermostat==1.1.1
 

requirements_test_all.txt

@@ -504,6 +504,9 @@ numpy==1.19.2
 # homeassistant.components.google
 oauth2client==4.0.0
 
+# homeassistant.components.profiler
+objgraph==3.4.1
+
 # homeassistant.components.omnilogic
 omnilogic==0.4.2
 

tests/components/profiler/test_init.py

@@ -1,16 +1,23 @@
 """Test the Profiler config flow."""
+from datetime import timedelta
 import os
 
 from homeassistant import setup
 from homeassistant.components.profiler import (
+    CONF_SCAN_INTERVAL,
     CONF_SECONDS,
+    CONF_TYPE,
+    SERVICE_DUMP_LOG_OBJECTS,
     SERVICE_MEMORY,
     SERVICE_START,
+    SERVICE_START_LOG_OBJECTS,
+    SERVICE_STOP_LOG_OBJECTS,
 )
 from homeassistant.components.profiler.const import DOMAIN
+import homeassistant.util.dt as dt_util
 
 from tests.async_mock import patch
-from tests.common import MockConfigEntry
+from tests.common import MockConfigEntry, async_fire_time_changed
 
 
 async def test_basic_usage(hass, tmpdir):
@@ -75,3 +82,68 @@ async def test_memory_usage(hass, tmpdir):
 
     assert await hass.config_entries.async_unload(entry.entry_id)
     await hass.async_block_till_done()
+
+
+async def test_object_growth_logging(hass, caplog):
+    """Test we can setup and the service and we can dump objects to the log."""
+
+    await setup.async_setup_component(hass, "persistent_notification", {})
+    entry = MockConfigEntry(domain=DOMAIN)
+    entry.add_to_hass(hass)
+
+    assert await hass.config_entries.async_setup(entry.entry_id)
+    await hass.async_block_till_done()
+
+    assert hass.services.has_service(DOMAIN, SERVICE_START_LOG_OBJECTS)
+    assert hass.services.has_service(DOMAIN, SERVICE_STOP_LOG_OBJECTS)
+
+    await hass.services.async_call(
+        DOMAIN, SERVICE_START_LOG_OBJECTS, {CONF_SCAN_INTERVAL: 10}
+    )
+    await hass.async_block_till_done()
+
+    assert "Growth" in caplog.text
+    caplog.clear()
+
+    async_fire_time_changed(hass, dt_util.utcnow() + timedelta(seconds=11))
+    await hass.async_block_till_done()
+    assert "Growth" in caplog.text
+
+    await hass.services.async_call(DOMAIN, SERVICE_STOP_LOG_OBJECTS, {})
+    await hass.async_block_till_done()
+    caplog.clear()
+
+    async_fire_time_changed(hass, dt_util.utcnow() + timedelta(seconds=21))
+    await hass.async_block_till_done()
+    assert "Growth" not in caplog.text
+
+    assert await hass.config_entries.async_unload(entry.entry_id)
+    await hass.async_block_till_done()
+
+    async_fire_time_changed(hass, dt_util.utcnow() + timedelta(seconds=31))
+    await hass.async_block_till_done()
+    assert "Growth" not in caplog.text
+
+
+async def test_dump_log_object(hass, caplog):
+    """Test we can setup and the service is registered and logging works."""
+
+    await setup.async_setup_component(hass, "persistent_notification", {})
+    entry = MockConfigEntry(domain=DOMAIN)
+    entry.add_to_hass(hass)
+
+    assert await hass.config_entries.async_setup(entry.entry_id)
+    await hass.async_block_till_done()
+
+    assert hass.services.has_service(DOMAIN, SERVICE_DUMP_LOG_OBJECTS)
+
+    await hass.services.async_call(
+        DOMAIN, SERVICE_DUMP_LOG_OBJECTS, {CONF_TYPE: "MockConfigEntry"}
+    )
+    await hass.async_block_till_done()
+
+    assert "MockConfigEntry" in caplog.text
+    caplog.clear()
+
+    assert await hass.config_entries.async_unload(entry.entry_id)
+    await hass.async_block_till_done()