mirror of
https://github.com/ChuckBuilds/LEDMatrix.git
synced 2026-08-20 01:49:05 +00:00
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.
This commit is contained in:
@@ -0,0 +1,63 @@
|
||||
"""The Vegas content path must trace at DEBUG, not 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", the per-item sizes -- and it does that for
|
||||
each plugin on each cycle.
|
||||
|
||||
Measured on a live rig: 13,408 log lines an hour, of which 13,366 were INFO and
|
||||
35 were WARNING. plugin_adapter alone produced 2,457 of them. That is ~223
|
||||
lines a minute of string formatting on a Pi that is also driving the panel, all
|
||||
of it written through journald to the SD card, and it buries the 35 lines that
|
||||
actually indicate a problem.
|
||||
|
||||
Nothing is lost by moving it to DEBUG: the 19 warning/error/exception calls in
|
||||
the module are untouched, so real failures still surface at their own level.
|
||||
|
||||
One INFO call is deliberate and stays -- the padding-strip message chooses its
|
||||
level at runtime (`logger.warning if (left and right) else logger.info`) and
|
||||
test_vegas_plugin_adapter.py pins it.
|
||||
"""
|
||||
import ast
|
||||
from pathlib import Path
|
||||
|
||||
import pytest
|
||||
|
||||
ADAPTER = (Path(__file__).resolve().parent.parent / "src" / "vegas_mode"
|
||||
/ "plugin_adapter.py")
|
||||
|
||||
|
||||
def _info_calls(path):
|
||||
"""Direct logger.info(...) call sites in a module."""
|
||||
tree = ast.parse(path.read_text(encoding="utf-8"))
|
||||
found = []
|
||||
for node in ast.walk(tree):
|
||||
if (isinstance(node, ast.Call)
|
||||
and isinstance(node.func, ast.Attribute)
|
||||
and node.func.attr == "info"
|
||||
and getattr(node.func.value, "id", None) == "logger"):
|
||||
found.append(node.lineno)
|
||||
return found
|
||||
|
||||
|
||||
def test_the_content_path_does_not_trace_at_info():
|
||||
calls = _info_calls(ADAPTER)
|
||||
assert not calls, (
|
||||
"plugin_adapter should trace at DEBUG; found logger.info at lines "
|
||||
f"{calls}. This path runs per plugin per cycle and its output goes to "
|
||||
"the SD card via journald."
|
||||
)
|
||||
|
||||
|
||||
def test_real_failures_still_have_a_level_of_their_own():
|
||||
"""Demoting the trace must not have swept up the error reporting."""
|
||||
source = ADAPTER.read_text(encoding="utf-8")
|
||||
loud = sum(source.count(f"logger.{level}(")
|
||||
for level in ("warning", "error", "exception"))
|
||||
assert loud >= 15, f"only {loud} warning/error/exception calls remain"
|
||||
|
||||
|
||||
def test_the_deliberate_runtime_chosen_level_survives():
|
||||
"""The padding-strip message picks its level at runtime; leave it alone."""
|
||||
source = ADAPTER.read_text(encoding="utf-8")
|
||||
assert "logger.warning if (left and right) else logger.info" in source
|
||||
Reference in New Issue
Block a user