From 7f6572893d392ece0b4eff0e820eeec0c513af93 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Sun, 18 Apr 2021 23:39:34 -1000 Subject: [PATCH] Add services to the profiler to log threads and event loop schedule (#49327) * Add services to the profiler to log threads and event loop schedule * improve readability * increase log debug * bigger * tweaks * Update homeassistant/components/profiler/__init__.py Co-authored-by: Martin Hjelmare * Update homeassistant/components/profiler/__init__.py Co-authored-by: Martin Hjelmare * remove schema= and cleanup existing Co-authored-by: Martin Hjelmare --- homeassistant/components/profiler/__init__.py | 52 ++++++++++++++++++- .../components/profiler/services.yaml | 4 ++ tests/components/profiler/test_init.py | 46 ++++++++++++++++ 3 files changed, 101 insertions(+), 1 deletion(-) diff --git a/homeassistant/components/profiler/__init__.py b/homeassistant/components/profiler/__init__.py index c3f4ab17686..e6aa2ce557d 100644 --- a/homeassistant/components/profiler/__init__.py +++ b/homeassistant/components/profiler/__init__.py @@ -3,7 +3,11 @@ import asyncio import cProfile from datetime import timedelta import logging +import reprlib +import sys +import threading import time +import traceback from guppy import hpy import objgraph @@ -23,6 +27,9 @@ SERVICE_MEMORY = "memory" SERVICE_START_LOG_OBJECTS = "start_log_objects" SERVICE_STOP_LOG_OBJECTS = "stop_log_objects" SERVICE_DUMP_LOG_OBJECTS = "dump_log_objects" +SERVICE_LOG_THREAD_FRAMES = "log_thread_frames" +SERVICE_LOG_EVENT_LOOP_SCHEDULED = "log_event_loop_scheduled" + SERVICES = ( SERVICE_START, @@ -30,6 +37,8 @@ SERVICES = ( SERVICE_START_LOG_OBJECTS, SERVICE_STOP_LOG_OBJECTS, SERVICE_DUMP_LOG_OBJECTS, + SERVICE_LOG_THREAD_FRAMES, + SERVICE_LOG_EVENT_LOOP_SCHEDULED, ) DEFAULT_SCAN_INTERVAL = timedelta(seconds=30) @@ -93,6 +102,34 @@ async def async_setup_entry(hass: HomeAssistant, entry: ConfigEntry): notification_id="profile_object_dump", ) + async def _async_dump_thread_frames(call: ServiceCall) -> None: + """Log all thread frames.""" + frames = sys._current_frames() # pylint: disable=protected-access + main_thread = threading.main_thread() + for thread in threading.enumerate(): + if thread == main_thread: + continue + _LOGGER.critical( + "Thread [%s]: %s", + thread.name, + "".join(traceback.format_stack(frames.get(thread.ident))).strip(), + ) + + async def _async_dump_scheduled(call: ServiceCall) -> None: + """Log all scheduled in the event loop.""" + arepr = reprlib.aRepr + original_maxstring = arepr.maxstring + original_maxother = arepr.maxother + arepr.maxstring = 300 + arepr.maxother = 300 + try: + for handle in hass.loop._scheduled: # pylint: disable=protected-access + if not handle.cancelled(): + _LOGGER.critical("Scheduled: %s", handle) + finally: + arepr.max_string = original_maxstring + arepr.max_other = original_maxother + async_register_admin_service( hass, DOMAIN, @@ -132,7 +169,6 @@ async def async_setup_entry(hass: HomeAssistant, entry: ConfigEntry): DOMAIN, SERVICE_STOP_LOG_OBJECTS, _async_stop_log_objects, - schema=vol.Schema({}), ) async_register_admin_service( @@ -143,6 +179,20 @@ async def async_setup_entry(hass: HomeAssistant, entry: ConfigEntry): schema=vol.Schema({vol.Required(CONF_TYPE): str}), ) + async_register_admin_service( + hass, + DOMAIN, + SERVICE_LOG_THREAD_FRAMES, + _async_dump_thread_frames, + ) + + async_register_admin_service( + hass, + DOMAIN, + SERVICE_LOG_EVENT_LOOP_SCHEDULED, + _async_dump_scheduled, + ) + return True diff --git a/homeassistant/components/profiler/services.yaml b/homeassistant/components/profiler/services.yaml index f0b04e9e002..2b59c7a4054 100644 --- a/homeassistant/components/profiler/services.yaml +++ b/homeassistant/components/profiler/services.yaml @@ -24,3 +24,7 @@ dump_log_objects: type: description: The type of objects to dump to the log example: State +log_thread_frames: + description: Log the current frames for all threads +log_event_loop_scheduled: + description: Log what is scheduled in the event loop diff --git a/tests/components/profiler/test_init.py b/tests/components/profiler/test_init.py index efed6ef6126..be376ea8aed 100644 --- a/tests/components/profiler/test_init.py +++ b/tests/components/profiler/test_init.py @@ -9,6 +9,8 @@ from homeassistant.components.profiler import ( CONF_SECONDS, CONF_TYPE, SERVICE_DUMP_LOG_OBJECTS, + SERVICE_LOG_EVENT_LOOP_SCHEDULED, + SERVICE_LOG_THREAD_FRAMES, SERVICE_MEMORY, SERVICE_START, SERVICE_START_LOG_OBJECTS, @@ -147,3 +149,47 @@ async def test_dump_log_object(hass, caplog): assert await hass.config_entries.async_unload(entry.entry_id) await hass.async_block_till_done() + + +async def test_log_thread_frames(hass, caplog): + """Test we can log thread frames.""" + + 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_LOG_THREAD_FRAMES) + + await hass.services.async_call(DOMAIN, SERVICE_LOG_THREAD_FRAMES, {}) + await hass.async_block_till_done() + + assert "SyncWorker_0" in caplog.text + caplog.clear() + + assert await hass.config_entries.async_unload(entry.entry_id) + await hass.async_block_till_done() + + +async def test_log_scheduled(hass, caplog): + """Test we can log scheduled items in the event loop.""" + + 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_LOG_EVENT_LOOP_SCHEDULED) + + await hass.services.async_call(DOMAIN, SERVICE_LOG_EVENT_LOOP_SCHEDULED, {}) + await hass.async_block_till_done() + + assert "Scheduled" in caplog.text + caplog.clear() + + assert await hass.config_entries.async_unload(entry.entry_id) + await hass.async_block_till_done()