Fix watchdog timeouts: memory throttling and tracemalloc snapshot stalls - #425
Conversation
tracemalloc was started with a 25-frame capture depth, but
dump_memory_stats() aggregates with statistics("lineno") and only ever
reads traceback[0] -- the other 24 frames were captured on every
allocation and discarded.
take_snapshot() cost scales with that depth. On a ~100M heap, snapshots
grew past 25s of synchronous work on the loop thread, which is long
enough to miss the systemd watchdog deadline: three separate watchdog
kills had tracebacks landing in _get_traces(), with the loop's scheduled
events overdue by 57-100s.
Depth 1 produces identical output at a fraction of the cost.
watchdog_ping() rescheduled itself only after SYSTEMD_NOTIFIER returned, so a single exception from the notify would drop the process out of the ping chain permanently. systemd then kills it WatchdogSec later, with nothing in the journal explaining why the pings stopped. Reschedule in a finally, so a failed notify costs one missed ping rather than all of them.
The unit capped the daemon well below its actual working set: ~57M steady state (interpreter, Jinja templates, compiled regexes, babel's CLDR tables) against MemoryHigh=50M. Crossing memory.high doesn't fail an allocation, it throttles the task in kernel reclaim -- and with MemorySwapMax=60M the overshoot became swap thrashing. The result was the loop parked in the kernel for 35-45s at a stretch, running no Python bytecode, which tripped the 10s watchdog. A deployment showed 44 memory.high throttle events with the peak pinned exactly at the limit. MemoryHigh=96M / MemoryMax=128M gives the working set room. Swap is now disabled outright: without it an overshoot is a prompt OOM kill and restart, which is far better than tens of seconds of thrashing. 30s of watchdog leaves margin for an ordinary reclaim stall while still catching a genuinely wedged loop within ten ping intervals.
ReviewDiagnosis in the description is well-evidenced, and it's unusually clear about separating what's proven from what's inferred. Three findings, one of which I think blocks merge as written. The
|
The finally added earlier was a no-op: thor's scheduler calls events bare and run() catches only KeyboardInterrupt, so an exception from the notify propagated out of thor.run() and killed the process either way -- the newly-scheduled ping never fired because the loop had already exited. The comment claiming the old behaviour was silent was wrong too; it crashed loudly with a traceback. Catch and log instead, so a transient notify failure costs one ping rather than dropping in-flight requests. Persistent failures still get the service killed, since the watchdog simply stops being fed. No finally, so a KeyboardInterrupt during the notify propagates without scheduling a stray ping on the way out. Adds test/test_daemon.py covering both paths; it fails against the previous version.
The ~45M tracemalloc figure was measured at a 25-frame capture depth, which this same branch drops to 1 -- the comment was stale on arrival. Say what it was measured at and point at memory.events for re-measuring rather than quoting a number that no longer holds. Also state outright that the limits assume --debug is off (96M against a ~57M working set is less headroom than debug mode was costing), and note that watchdog_freq is hardcoded rather than derived from WATCHDOG_USEC, so the two have to be kept in step by hand.
|
All three points addressed. Two new commits. The
|
1 participant
Diagnoses and addresses repeated
redbot.service: Watchdog timeoutkills on redbot.org.Root causes
Two independent sources of multi-second event-loop stalls, both of which trip the systemd watchdog.
1. cgroup memory throttling. The shipped unit capped the daemon well below its actual working set —
MemoryHigh=50Magainst ~57M steady state (interpreter, Jinja templates, compiled regexes, babel's CLDR tables). Crossingmemory.highdoesn't fail an allocation; the kernel throttles the task in reclaim. WithMemorySwapMax=60Mon top, an overshoot became swap thrashing. The signature in the journal is distinctive: SIGABRT delivered at 04:11:25, but Python didn't run its handler until 04:12:00 — 35 seconds during which the main thread executed no bytecode at all, with scheduled events overdue by 37s. A live deployment showedmemory.events: high 44withMemoryPeakpinned exactly at the limit.2.
tracemallocsnapshots under--debug.tracemalloc.start(25)captured 25-frame tracebacks on every allocation, butdump_memory_stats()aggregates withstatistics("lineno")and only ever readstraceback[0]— the other 24 frames were captured and discarded.take_snapshot()cost scales with that depth: completed dumps grew from 2s to 25s as the heap grew, and three watchdog kills have tracebacks landing directly in_get_traces(), each firing ~27s after the dump began.Changes
tracemalloc.start(25)→start(1)— identical output, a fraction of the cost.watchdog_ping()reschedules in afinally— it previously rescheduled only afterSYSTEMD_NOTIFIERreturned, so one exception from the notify would drop the process out of the ping chain permanently and systemd would kill itWatchdogSeclater with nothing in the journal to explain why. Unrelated to these incidents, but a trap worth closing.MemoryHigh=96M,MemoryMax=128M,MemorySwapMax=0,WatchdogSec=30, with comments recording the measured working set and the reasoning. Swap is now off deliberately: an overshoot becomes a prompt OOM kill and restart rather than tens of seconds of thrashing.For reviewers
MemoryPeakthat was itself pinned against the old 50MMemoryHigh, so it understates what the process actually wants. Once--debugis off in production,MemoryPeakplus a flathighcounter will give the true number, and the limits can be tightened.try/finallychange is verified by inspection only. It needsSYSTEMD_WATCHDOGand cysystemd, so it doesn't exercise on macOS.systemd-analyze verifyisn't available on the dev machine.tracemallocsnapshots. Two others (20:04, 04:10) produced no usable traceback and needed SIGKILL — consistent with the memory-throttling mechanism, but not individually proven. Turning--debugoff removes both the snapshot stalls and ~45M of overhead; anything that still trips after that is a genuine remaining bug, and withhighstaying flat it will be cleanly diagnosable for the first time.chardetaccounts for 22.2 MiB in every dump — ten times everything else combined, and constant across processes. It isn't a redbot dependency; it arrives viahttplint 2026.05.2. Probably its lazily-loaded language-model tables rather than retained body copies, but unconfirmed.Verified with
make typecheck,make lint(10.00/10), andmake test(37 passed), each checked by exit code. Also ran the daemon end-to-end with-d: starts, serves 200 on/, and SIGTERM produces the expected memory dump.🤖 Written by Claude Opus 4.8 in Claude Code. The diagnosis was developed interactively with @mnot over the course of the investigation — he supplied the journal excerpts and
memory.eventsoutput, adjusted the deployed unit himself, and reviewed the reasoning at each step before approving these three changes. The code and this description are AI-generated; the conclusions were checked against live production data by a human.