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 <marhje52@gmail.com>

* Update homeassistant/components/profiler/__init__.py

Co-authored-by: Martin Hjelmare <marhje52@gmail.com>

* remove schema= and cleanup existing

Co-authored-by: Martin Hjelmare <marhje52@gmail.com>

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
 
 

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

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()