perf: cut SD writes and log volume, and give the journal real severities - #475
Closed
ChuckBuilds wants to merge 4 commits into
Closed
perf: cut SD writes and log volume, and give the journal real severities#475ChuckBuilds wants to merge 4 commits into
ChuckBuilds wants to merge 4 commits into
Conversation
Every successful plugin update called record_success(), which persisted the record unconditionally. In steady state the only fields that had changed were total_successes and last_success_time -- a counter and a timestamp that health_monitor surfaces for display and that nothing reads back after a restart. Nothing alerts on the age of last_successful_update; it is carried in the metrics dataclass and shown. Measured on a rig running 24 plugins, all steady-state (0 consecutive failures, circuit closed): a five-minute sample caught 22 health-file rewrites, about 4.4 a minute or 6,300 a day. Each write is ~400 bytes through cache_manager.set(), which writes a file per call, so each one costs a filesystem block plus an ext4 journal write. That lands on an SD card, where the unit of cost is an erase-block cycle rather than the bytes involved, and where wear is what eventually kills the card. Two cards have already failed on the other rig with the same signature -- unreadable block device, EIO on exec, sshd unable to read its host keys. The circuit breaker still has to survive a restart, so the write is kept for exactly the fields it is rebuilt from: consecutive_failures, circuit_state, circuit_opened_time, half_open_start_time. A failure, a circuit opening and a recovery are all still written the moment they happen. In-memory state is updated every time either way, so the health API and web UI show what they always did. Tested: 100 healthy cycles now perform zero writes after the first, the counters remain accurate in memory, and a failure, a recovery and a half-open-to-closed transition each still reach disk. One test kills and rebuilds the tracker from the cache to prove the breaker's state genuinely survives what is no longer written. Mutation-checked both ways: persisting unconditionally again fails the steady-state test, and widening _DURABLE_FIELDS to include last_success_time fails it too. The 46 existing health tests pass. (cherry picked from commit 14abea2) (cherry picked from commit 0f77bd2)
plugin_adapter narrates every step of acquiring content from every plugin --
"Has get_vegas_content", "Native: calling get_vegas_content()", "Native
content returned None", "Has scroll_helper", per-item sizes -- once per plugin
per cycle, all at INFO.
Measured on a live rig: 13,408 log lines an hour, of which 13,366 were INFO
and 35 were WARNING. Roughly 223 lines a minute of string formatting on a Pi
that is also driving the panel, written through journald to the SD card, with
the 35 lines that actually indicate a problem buried among them.
Top repeated messages in that hour:
717 Scroll progress: elapsed=... total_scrolled=.../... px
399 [plugin] --> INCLUDED in Vegas scroll
323 [plugin] content_type=static, display_mode=fixed
195 [plugin] Has get_vegas_content: True
195 [plugin] Native: calling get_vegas_content()
168 [plugin] Native: get_vegas_content() returned None
168 [plugin] Native content returned None <- the same fact, twice
54 logger.info calls in plugin_adapter become logger.debug, along with the
per-frame scroll-progress line in scroll_helper. Together those are 3,174 of
the 13,408 lines an hour, a 23% cut, and the ~3,600 odds-manager lines are
addressed separately by ledmatrix-plugins#300.
Nothing is lost: the 19 warning/error/exception calls in the module are
untouched, so real failures still surface at their own level. This is a
logging-level change only -- no control flow, no behaviour.
One INFO call is deliberate and stays. The padding-strip message picks its
level at runtime (`logger.warning if (left and right) else logger.info`) and
test_vegas_plugin_adapter.py pins that choice; it survives because it is not a
direct logger.info call site. That test still passes.
Mutation-checked both ways: reintroducing a single INFO trace fails the guard,
and demoting the warning/error calls along with the trace fails a second guard
written for exactly that mistake. 537 vegas and scroll tests pass.
(cherry picked from commit e496d95)
(cherry picked from commit 8d1e43c)
Everything this process writes to stdout reaches the journal as PRIORITY=6,
whatever the Python level was, because journald has nothing else to go on.
Measured on a live rig over 24 hours:
lines containing " - ERROR - " 55
lines containing " - WARNING - " 13
journald PRIORITY recorded 6, for every one of them
So `journalctl -p err -u ledmatrix` returns nothing while errors are being
logged, and `-p warning` likewise. Triage falls back to grepping message text,
which is slower and unreliable: during this audit a search for "oom" matched
the radar logging "zoom=9" twenty-four times and briefly looked like the OOM
killer had been firing.
systemd reads a leading "<N>" on each stdout line and takes it as the priority
(sd-daemon(3)), so a formatter that prefixes one costs no dependency. Every
line of a multi-line record is tagged, not just the first -- the journal splits
them, and an untagged continuation reverts to the default, which would leave
the body of a traceback filed as informational while its first line was an
error.
Applied only when JOURNAL_STREAM is set, which systemd sets for services whose
output it captures. Run from a terminal, in the emulator or under pytest the
prefixes would be literal noise, and the file handler keeps the plain
formatter for the same reason.
Mutation-checked three ways: prefixing unconditionally fails the
outside-systemd test, prefixing only the first line fails the multi-line test,
and mapping ERROR to 6 fails the level mapping. 39 tests pass across the
logging suites.
(cherry picked from commit 780fca6)
Contributor
|
Warning Review limit reached
Next review available in: 21 minutes Limit details: You’ve used the included review currently available. You've used all free OSS reviews for now. Wait for the free limit to reset to keep reviewing this public repository. How can I continue?Wait for the limit to reset, then comment An organization admin can change what happens after included review limits in Billing. How do review limits work?CodeRabbit enforces per-developer PR review limits within each organization. For paid Pro and Pro+ reviews, CodeRabbit uses a developer's included PR review attempts over the past 7 days to set the current hourly allowance. At typical activity levels, the full plan allowance applies. Higher sustained activity can lower the allowance until earlier attempts leave the 7-day window. Please refer docs for additional details. Review details⚙️ Run configurationConfiguration used: Organization UI Review profile: CHILL Plan: Pro Plus Run ID: 📒 Files selected for processing (8)
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
Up to standards ✅🟢 Issues
|
| Metric | Results |
|---|---|
| Complexity | 6 |
| Duplication | 0 |
NEW Get contextual insights on your PRs based on Codacy's metrics, along with PR and Jira context, without leaving GitHub. Enable AI reviewer
TIP This summary will be updated as you push new changes.
This was referenced Aug 20, 2026
CI caught what local testing could not: two existing tests in test_logging_config.py assert that setup_logging() selected a StructuredFormatter or a ContextualFormatter, by checking the console handler's formatter directly. Wrapping that formatter to tag each line with its syslog priority makes those assertions false. They passed locally and failed on the runner because the wrapper is applied only when JOURNAL_STREAM is set -- absent in a terminal, present in CI. An environment-dependent break, which is the kind that gets shipped. The wrapper now exposes the formatter it delegates to, and those two tests look through it. They are about which formatter format_type selects, and that behaviour is unchanged; only the object they have to reach for moved. Verified both ways this time: 39 tests pass with JOURNAL_STREAM set and with it unset.
This was referenced Aug 20, 2026
Owner
Author
|
Superseded by #486, which combines the three SD-write/log-volume PRs. Every change from this PR is verified present on that branch; the branch here is untouched if you want to compare. |
ChuckBuilds
added a commit
that referenced
this pull request
Aug 21, 2026
* fix(plugins): one bad metrics cache entry should not stop every plugin
Caught live on a rig: every plugin failing, once each, continuously.
ERROR - src.plugin_system.plugin_manager - plugin geochron operation failed:
ResourceMetrics.__init__() got an unexpected keyword argument
'consecutive_failures'
ERROR - ... plugin text-display operation failed: ...
ERROR - ... plugin news operation failed: ...
ERROR - ... plugin odds-ticker operation failed: ...
with /api/v3/health reporting plugin_system: not_initialized while the display
process itself kept running and updating the panel.
`consecutive_failures` is a plugin_health field, not a metrics one.
get_metrics() does ResourceMetrics(**cached), which raises TypeError on a
single unrecognised key, and that exception escapes into plugin_manager and is
reported per plugin. One malformed cache entry takes the whole plugin system
down.
How a health-shaped record came to sit under a plugin_metrics key on that
machine is not established, and I could not finish the diagnosis: the rig went
back into its EIO failure mode partway through -- SSH resetting pre-banner,
systemctl unexecutable -- while the web API kept answering from RAM. Checked
before that: the cache files on disk are correctly shaped and separate, and
CacheManager.get() returns the right record for each key, so it is not a live
key collision. A restored backup mixing two machines' caches is the likeliest
explanation, and that rig had one restored onto it.
Either way the loader should not be brittle enough for the answer to matter.
plugin_health already repairs its records field by field rather than trusting
what is on disk; this does the same. Known fields are kept, unknown ones are
dropped and named once in the log so a genuine schema change stays visible
rather than being silently discarded, and a non-mapping entry no longer raises.
Keeping the known fields matters: discarding the record wholesale would throw
away real call counts and timings because of an unrelated stray key.
Mutation-checked: restoring ResourceMetrics(**cached) fails 6 checks, dropping
the whole record fails the field-preservation check, and dropping unknown
fields silently fails the logging check. 28 tests pass across the resource
monitor and plugin health suites.
* perf(health): stop rewriting a health record on every healthy cycle
Every successful plugin update called record_success(), which persisted the
record unconditionally. In steady state the only fields that had changed were
total_successes and last_success_time -- a counter and a timestamp that
health_monitor surfaces for display and that nothing reads back after a
restart. Nothing alerts on the age of last_successful_update; it is carried in
the metrics dataclass and shown.
Measured on a rig running 24 plugins, all steady-state (0 consecutive
failures, circuit closed): a five-minute sample caught 22 health-file
rewrites, about 4.4 a minute or 6,300 a day. Each write is ~400 bytes through
cache_manager.set(), which writes a file per call, so each one costs a
filesystem block plus an ext4 journal write.
That lands on an SD card, where the unit of cost is an erase-block cycle
rather than the bytes involved, and where wear is what eventually kills the
card. Two cards have already failed on the other rig with the same
signature -- unreadable block device, EIO on exec, sshd unable to read its
host keys.
The circuit breaker still has to survive a restart, so the write is kept for
exactly the fields it is rebuilt from: consecutive_failures, circuit_state,
circuit_opened_time, half_open_start_time. A failure, a circuit opening and a
recovery are all still written the moment they happen. In-memory state is
updated every time either way, so the health API and web UI show what they
always did.
Tested: 100 healthy cycles now perform zero writes after the first, the
counters remain accurate in memory, and a failure, a recovery and a
half-open-to-closed transition each still reach disk. One test kills and
rebuilds the tracker from the cache to prove the breaker's state genuinely
survives what is no longer written.
Mutation-checked both ways: persisting unconditionally again fails the
steady-state test, and widening _DURABLE_FIELDS to include last_success_time
fails it too. The 46 existing health tests pass.
(cherry picked from commit 14abea2)
(cherry picked from commit 0f77bd2)
* perf(vegas): trace the content path at DEBUG instead of INFO
plugin_adapter narrates every step of acquiring content from every plugin --
"Has get_vegas_content", "Native: calling get_vegas_content()", "Native
content returned None", "Has scroll_helper", per-item sizes -- once per plugin
per cycle, all at INFO.
Measured on a live rig: 13,408 log lines an hour, of which 13,366 were INFO
and 35 were WARNING. Roughly 223 lines a minute of string formatting on a Pi
that is also driving the panel, written through journald to the SD card, with
the 35 lines that actually indicate a problem buried among them.
Top repeated messages in that hour:
717 Scroll progress: elapsed=... total_scrolled=.../... px
399 [plugin] --> INCLUDED in Vegas scroll
323 [plugin] content_type=static, display_mode=fixed
195 [plugin] Has get_vegas_content: True
195 [plugin] Native: calling get_vegas_content()
168 [plugin] Native: get_vegas_content() returned None
168 [plugin] Native content returned None <- the same fact, twice
54 logger.info calls in plugin_adapter become logger.debug, along with the
per-frame scroll-progress line in scroll_helper. Together those are 3,174 of
the 13,408 lines an hour, a 23% cut, and the ~3,600 odds-manager lines are
addressed separately by ledmatrix-plugins#300.
Nothing is lost: the 19 warning/error/exception calls in the module are
untouched, so real failures still surface at their own level. This is a
logging-level change only -- no control flow, no behaviour.
One INFO call is deliberate and stays. The padding-strip message picks its
level at runtime (`logger.warning if (left and right) else logger.info`) and
test_vegas_plugin_adapter.py pins that choice; it survives because it is not a
direct logger.info call site. That test still passes.
Mutation-checked both ways: reintroducing a single INFO trace fails the guard,
and demoting the warning/error calls along with the trace fails a second guard
written for exactly that mistake. 537 vegas and scroll tests pass.
(cherry picked from commit e496d95)
(cherry picked from commit 8d1e43c)
* fix(logging): give the journal the real severity of each line
Everything this process writes to stdout reaches the journal as PRIORITY=6,
whatever the Python level was, because journald has nothing else to go on.
Measured on a live rig over 24 hours:
lines containing " - ERROR - " 55
lines containing " - WARNING - " 13
journald PRIORITY recorded 6, for every one of them
So `journalctl -p err -u ledmatrix` returns nothing while errors are being
logged, and `-p warning` likewise. Triage falls back to grepping message text,
which is slower and unreliable: during this audit a search for "oom" matched
the radar logging "zoom=9" twenty-four times and briefly looked like the OOM
killer had been firing.
systemd reads a leading "<N>" on each stdout line and takes it as the priority
(sd-daemon(3)), so a formatter that prefixes one costs no dependency. Every
line of a multi-line record is tagged, not just the first -- the journal splits
them, and an untagged continuation reverts to the default, which would leave
the body of a traceback filed as informational while its first line was an
error.
Applied only when JOURNAL_STREAM is set, which systemd sets for services whose
output it captures. Run from a terminal, in the emulator or under pytest the
prefixes would be literal noise, and the file handler keeps the plain
formatter for the same reason.
Mutation-checked three ways: prefixing unconditionally fails the
outside-systemd test, prefixing only the first line fails the multi-line test,
and mapping ERROR to 6 fails the level mapping. 39 tests pass across the
logging suites.
(cherry picked from commit 780fca6)
* fix(logging): let callers see through the journald formatter wrapper
CI caught what local testing could not: two existing tests in
test_logging_config.py assert that setup_logging() selected a
StructuredFormatter or a ContextualFormatter, by checking the console
handler's formatter directly. Wrapping that formatter to tag each line with
its syslog priority makes those assertions false.
They passed locally and failed on the runner because the wrapper is applied
only when JOURNAL_STREAM is set -- absent in a terminal, present in CI. An
environment-dependent break, which is the kind that gets shipped.
The wrapper now exposes the formatter it delegates to, and those two tests
look through it. They are about which formatter format_type selects, and that
behaviour is unchanged; only the object they have to reach for moved.
Verified both ways this time: 39 tests pass with JOURNAL_STREAM set and with
it unset.
* perf(plugins): stop rewriting a plugin's metrics file on every call
Plugin metrics were persisted to the cache inside monitor_call, so every
call by every plugin rewrote a small JSON file. Measured on a running rig:
one plugin's plugin_metrics file changed nine times a minute, with fourteen
such files active. Each is around 350 bytes, which on ext4 costs a 4KB block
plus a journal entry, so the cost is dominated by the write itself rather
than the payload. Cache writes accounted for essentially all of that device's
2.4 MB/min of SD traffic, on a card that wears out and has already failed
twice on the other rig.
Metrics cannot be de-duplicated the way health state can, because call_count
changes on every call and the timings usually do too. So they are rate-limited
instead: at most one write per plugin per 30 seconds.
The in-memory copy stays authoritative and exact -- a plugin's call_count is
still precise the instant after it runs. Only the cross-process snapshot the
web UI reads is delayed, and telemetry up to half a minute old is still a fair
description of a long-running plugin.
reset_metrics clears the throttle timestamp, so a reset is not left showing a
deleted key for the rest of the interval.
Extrapolating the sampled rate, this takes metric writes from roughly 126 a
minute to 28. Health persistence, the other half of the churn, is handled
separately in #475.
Verified by reverting the throttle: the churn test then reports 50 writes for
50 calls. 88 tests pass across resource monitor, plugin system and web API.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01STMbQE4YctTacQXfbYqKuW
* fix: use a monotonic clock and only mark metrics persisted once written
Two review findings on the throttle, both right.
The interval compared wall-clock timestamps. These devices have no RTC, so
the clock jumps by however far off boot-time was the moment NTP first syncs
-- a forward jump would allow an early write, a backward one would stall the
snapshot well past the interval. time.monotonic() is not subject to either.
The timestamp was also recorded before cache_manager.set(). A set() that
raised would buy the next interval's silence without leaving a snapshot
behind, which is the one case where skipping the write is least affordable.
Recorded after the write lands instead, so a failure is retried on the next
call.
Verified by restoring the original ordering: the new test then reports one
write where two are expected.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01STMbQE4YctTacQXfbYqKuW
* Address all six review findings on the perf consolidation
CodeRabbit reported six; this is all six, checked against its own
"Actionable comments posted: 6" rather than against what I happened to
scroll past.
Three are real defects in the code:
1. _under_systemd() trusted the presence of JOURNAL_STREAM.
systemd publishes JOURNAL_STREAM as "dev:ino", and every child process
inherits it -- including one whose stdout has been redirected to a pipe
or a file. The variable outlives the descriptor it describes, so a
subprocess would decide it was talking to the journal and emit the "<N>"
priority prefixes as literal noise into that captured output. That is
exactly the noise the function exists to prevent. It now parses the pair
and fstats stdout, per systemd's own guidance, and returns False for
missing, malformed, mismatched, or unusable descriptors.
2. Cached metrics were not type-checked.
A dataclass does not enforce its annotations, so
ResourceMetrics(call_count="not a number") builds happily and only
fails later, deep inside monitor_call:
TypeError: can only concatenate str (not "int") to str
Values are now coerced to their declared type at load, where there is
still a cache key to name in the warning, and a value that cannot be
coerced starts the plugin fresh instead of arming a delayed failure.
A numeric string is accepted rather than discarded -- a JSON round-trip
can widen an int, and that is recoverable.
3. The first metrics snapshot was skipped for the first 30s of uptime.
_persist_metrics used 0.0 as the "never written" default. monotonic() is
time since boot on Linux and systemd starts this service at boot, so
`now - 0.0 < 30` was true for the first half-minute of every run: the
throttle swallowed the very first write, the one that matters most after
a restart. The sentinel is now None and the interval is only applied when
a previous write exists.
Three are tests that could pass without testing anything:
4. test_health_write_churn's fake cache stored by reference, so the
tracker kept mutating the object already in the store -- a record
could look persisted when no write had happened, which is precisely
what test_durable_state_survives_a_restart exists to detect. Both
directions now deep-copy, like a cache that serialises to a file.
Verified: disabling the one real cache write now fails three tests.
5. test_values_of_the_wrong_type_do_not_raise asserted only that a
dataclass had been constructed, which was true with the bad value
still in it. It now asserts the loaded metrics are usable -- the
field is numeric, and arithmetic on it does not raise -- across four
kinds of bad value.
6. test_vegas_log_volume counted "logger.error(" in the source text,
which also matches comments, docstrings and string literals --
including that module's own docstring, which names those levels. A
real error call could be demoted with the tally unmoved. It now walks
the AST, reusing the helper already in the file. Verified: demoting
all 18 warning/error/exception calls now fails the test.
Verified: every fix mutation-checked by reverting it and confirming the
matching test fails.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01STMbQE4YctTacQXfbYqKuW
---------
Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Consolidates #468 and #473 into one review, because CodeRabbit is rate-limiting across the queue. All three commits are cherry-picked with
-xand unchanged; the originals will be closed pointing here.Three independent changes, each measured on a live rig. They touch different files and can be reviewed separately.
1. A health record was rewritten on every healthy cycle
record_success()fires on every successful plugin update and persisted unconditionally. In steady state the only changed fields weretotal_successesandlast_success_time— a counter and a timestamp that nothing reads back after a restart.Measured on a rig with 24 plugins, all steady-state: a five-minute sample caught 22 rewrites, ~4.4/min, ~6,300/day.
Persisting is now limited to the four fields the circuit breaker is rebuilt from. Failures, circuit openings and recoveries still write immediately.
2. The Vegas content path traced at INFO
13,408 log lines/hour — 13,366 INFO, 35 WARNING, 5 ERROR. ~223 lines/min of string formatting on a Pi that is also driving the panel, written through journald to the SD card.
54
logger.info→logger.debug, plus the per-frame scroll-progress line. 13,408 → 10,234 lines/hour, a 23% cut. The 19 warning/error/exception calls are untouched, and one deliberate INFO call — whose level is chosen at runtime and pinned by an existing test — survives.3. Every log line reached the journal as informational
Over 24 hours: 55 lines containing
- ERROR -, 13 containing- WARNING -, and journald recordedPRIORITY=6for every one. Sojournalctl -p err -u ledmatrixreturns nothing while errors are being logged.That cost me real time during this audit: triage falls back to grepping message text, and a search for
oommatched the radar loggingzoom=9twenty-four times, briefly looking like the OOM killer had fired.systemd reads a leading
<N>on each stdout line as the priority, so this needs no dependency. Every line of a multi-line record is tagged — the journal splits them, and an untagged continuation would file the body of a traceback as informational. Applied only whenJOURNAL_STREAMis set, so terminal, emulator and pytest output stay clean.These two interact: with real priorities, change 2's log-volume reduction can be judged with
journalctl -p warningrather than by eye.Verification
60 tests pass across the health, vegas, scroll and logging suites.
Mutation-checked, seven ways:
_DURABLE_FIELDSto includelast_success_time🤖 Generated with Claude Code
https://claude.ai/code/session_01STMbQE4YctTacQXfbYqKuW