Add service to log all the current asyncio Tasks to the profiler (#116389)

* Add service to log all the current asyncio Tasks to the profiler

I have been helping users look for a task leaks, and need a
way to examine tasks at run time as trying to get someone to
run Home Assistant and attach aiomonitor is too difficult in
many cases.

* cover
This commit is contained in:
J. Nick Koston 2024-04-29 10:03:35 -05:00 committed by GitHub
parent f1e5bbcbca
commit 8bfcaf3524
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
5 changed files with 64 additions and 10 deletions

View file

@ -1,6 +1,8 @@
"""The profiler integration.""" """The profiler integration."""
import asyncio import asyncio
from collections.abc import Generator
import contextlib
from contextlib import suppress from contextlib import suppress
from datetime import timedelta from datetime import timedelta
from functools import _lru_cache_wrapper from functools import _lru_cache_wrapper
@ -37,6 +39,7 @@ SERVICE_LRU_STATS = "lru_stats"
SERVICE_LOG_THREAD_FRAMES = "log_thread_frames" SERVICE_LOG_THREAD_FRAMES = "log_thread_frames"
SERVICE_LOG_EVENT_LOOP_SCHEDULED = "log_event_loop_scheduled" SERVICE_LOG_EVENT_LOOP_SCHEDULED = "log_event_loop_scheduled"
SERVICE_SET_ASYNCIO_DEBUG = "set_asyncio_debug" SERVICE_SET_ASYNCIO_DEBUG = "set_asyncio_debug"
SERVICE_LOG_CURRENT_TASKS = "log_current_tasks"
_LRU_CACHE_WRAPPER_OBJECT = _lru_cache_wrapper.__name__ _LRU_CACHE_WRAPPER_OBJECT = _lru_cache_wrapper.__name__
_SQLALCHEMY_LRU_OBJECT = "LRUCache" _SQLALCHEMY_LRU_OBJECT = "LRUCache"
@ -59,6 +62,7 @@ SERVICES = (
SERVICE_LOG_THREAD_FRAMES, SERVICE_LOG_THREAD_FRAMES,
SERVICE_LOG_EVENT_LOOP_SCHEDULED, SERVICE_LOG_EVENT_LOOP_SCHEDULED,
SERVICE_SET_ASYNCIO_DEBUG, SERVICE_SET_ASYNCIO_DEBUG,
SERVICE_LOG_CURRENT_TASKS,
) )
DEFAULT_SCAN_INTERVAL = timedelta(seconds=30) DEFAULT_SCAN_INTERVAL = timedelta(seconds=30)
@ -241,21 +245,20 @@ async def async_setup_entry( # noqa: C901
"".join(traceback.format_stack(frames.get(ident))).strip(), "".join(traceback.format_stack(frames.get(ident))).strip(),
) )
async def _async_dump_current_tasks(call: ServiceCall) -> None:
"""Log all current tasks in the event loop."""
with _increase_repr_limit():
for task in asyncio.all_tasks():
if not task.cancelled():
_LOGGER.critical("Task: %s", _safe_repr(task))
async def _async_dump_scheduled(call: ServiceCall) -> None: async def _async_dump_scheduled(call: ServiceCall) -> None:
"""Log all scheduled in the event loop.""" """Log all scheduled in the event loop."""
arepr = reprlib.aRepr with _increase_repr_limit():
original_maxstring = arepr.maxstring handle: asyncio.Handle
original_maxother = arepr.maxother
arepr.maxstring = 300
arepr.maxother = 300
handle: asyncio.Handle
try:
for handle in getattr(hass.loop, "_scheduled"): for handle in getattr(hass.loop, "_scheduled"):
if not handle.cancelled(): if not handle.cancelled():
_LOGGER.critical("Scheduled: %s", handle) _LOGGER.critical("Scheduled: %s", handle)
finally:
arepr.maxstring = original_maxstring
arepr.maxother = original_maxother
async def _async_asyncio_debug(call: ServiceCall) -> None: async def _async_asyncio_debug(call: ServiceCall) -> None:
"""Enable or disable asyncio debug.""" """Enable or disable asyncio debug."""
@ -372,6 +375,13 @@ async def async_setup_entry( # noqa: C901
schema=vol.Schema({vol.Optional(CONF_ENABLED, default=True): cv.boolean}), schema=vol.Schema({vol.Optional(CONF_ENABLED, default=True): cv.boolean}),
) )
async_register_admin_service(
hass,
DOMAIN,
SERVICE_LOG_CURRENT_TASKS,
_async_dump_current_tasks,
)
return True return True
@ -573,3 +583,18 @@ def _log_object_sources(
_LOGGER.critical("New objects overflowed by %s", new_objects_overflow) _LOGGER.critical("New objects overflowed by %s", new_objects_overflow)
elif not had_new_object_growth: elif not had_new_object_growth:
_LOGGER.critical("No new object growth found") _LOGGER.critical("No new object growth found")
@contextlib.contextmanager
def _increase_repr_limit() -> Generator[None, None, None]:
"""Increase the repr limit."""
arepr = reprlib.aRepr
original_maxstring = arepr.maxstring
original_maxother = arepr.maxother
arepr.maxstring = 300
arepr.maxother = 300
try:
yield
finally:
arepr.maxstring = original_maxstring
arepr.maxother = original_maxother

View file

@ -8,6 +8,7 @@
"start_log_object_sources": "mdi:play", "start_log_object_sources": "mdi:play",
"stop_log_object_sources": "mdi:stop", "stop_log_object_sources": "mdi:stop",
"lru_stats": "mdi:chart-areaspline", "lru_stats": "mdi:chart-areaspline",
"log_current_tasks": "mdi:format-list-bulleted",
"log_thread_frames": "mdi:format-list-bulleted", "log_thread_frames": "mdi:format-list-bulleted",
"log_event_loop_scheduled": "mdi:calendar-clock", "log_event_loop_scheduled": "mdi:calendar-clock",
"set_asyncio_debug": "mdi:bug-check" "set_asyncio_debug": "mdi:bug-check"

View file

@ -59,3 +59,4 @@ set_asyncio_debug:
default: true default: true
selector: selector:
boolean: boolean:
log_current_tasks:

View file

@ -93,6 +93,10 @@
"description": "Whether to enable or disable asyncio debug." "description": "Whether to enable or disable asyncio debug."
} }
} }
},
"log_current_tasks": {
"name": "Log current asyncio tasks",
"description": "Logs all the current asyncio tasks."
} }
} }
} }

View file

@ -18,6 +18,7 @@ from homeassistant.components.profiler import (
CONF_ENABLED, CONF_ENABLED,
CONF_SECONDS, CONF_SECONDS,
SERVICE_DUMP_LOG_OBJECTS, SERVICE_DUMP_LOG_OBJECTS,
SERVICE_LOG_CURRENT_TASKS,
SERVICE_LOG_EVENT_LOOP_SCHEDULED, SERVICE_LOG_EVENT_LOOP_SCHEDULED,
SERVICE_LOG_THREAD_FRAMES, SERVICE_LOG_THREAD_FRAMES,
SERVICE_LRU_STATS, SERVICE_LRU_STATS,
@ -221,6 +222,28 @@ async def test_log_thread_frames(
await hass.async_block_till_done() await hass.async_block_till_done()
async def test_log_current_tasks(
hass: HomeAssistant, caplog: pytest.LogCaptureFixture
) -> None:
"""Test we can log current tasks."""
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_CURRENT_TASKS)
await hass.services.async_call(DOMAIN, SERVICE_LOG_CURRENT_TASKS, {}, blocking=True)
assert "test_log_current_tasks" 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( async def test_log_scheduled(
hass: HomeAssistant, caplog: pytest.LogCaptureFixture hass: HomeAssistant, caplog: pytest.LogCaptureFixture
) -> None: ) -> None: