diff --git a/homeassistant/components/profiler/__init__.py b/homeassistant/components/profiler/__init__.py index b4cca97e1fd..c8f6c9fd1a2 100644 --- a/homeassistant/components/profiler/__init__.py +++ b/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)) diff --git a/homeassistant/components/profiler/manifest.json b/homeassistant/components/profiler/manifest.json index c1be2025fb6..b448e3d1793 100644 --- a/homeassistant/components/profiler/manifest.json +++ b/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 diff --git a/homeassistant/components/profiler/services.yaml b/homeassistant/components/profiler/services.yaml index e1c1db89688..f0b04e9e002 100644 --- a/homeassistant/components/profiler/services.yaml +++ b/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 diff --git a/requirements_all.txt b/requirements_all.txt index f40a7e0a693..af0f6b59d47 100644 --- a/requirements_all.txt +++ b/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 diff --git a/requirements_test_all.txt b/requirements_test_all.txt index 6c9cbdc61e5..5cf7f074734 100644 --- a/requirements_test_all.txt +++ b/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 diff --git a/tests/components/profiler/test_init.py b/tests/components/profiler/test_init.py index d2daa117a43..0ccda904eb6 100644 --- a/tests/components/profiler/test_init.py +++ b/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()