diff --git a/CHANGELOG.md b/CHANGELOG.md index 1cc6a860..7b35b98c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -19,6 +19,25 @@ accepts both, but the store flags the old spelling as deprecated ## Unreleased +### Scroll speed: a panel slower than its refresh cap is reported + +- Scroll speeds are solved against `limit_refresh_rate_hz`, so a panel that + cannot reach its cap ran every scroll slow by the shortfall, with no sign + why (one Pi 4 on a 120 Hz cap refreshed at ~110 Hz: 60 px/s ran at 55). + Once the display has measured the real rate over three windows of + scrolling, a panel more than 3% short of the cap is logged once, as a + warning from `src.common.frame_timing` that names a cap it can hold (a + multiple of 10, 5% under the measurement). The Display tab shows the same + under Limit Refresh Rate, with a button that fills it in, from the new + `GET /api/v3/config/refresh-rate`. Not checked in the emulator or on the + fallback canvas. +- The frame-stats file records `planned_refresh_hz` (additive), and the + scroll-speed advice behind the Vegas slider ignores a measurement written + under a different cap. Until now, after the cap changed, the slider kept + advising from the old rate until the display restarted. +- New in `src.common.scroll_config`: `refresh_shortfall()`, `holdable_cap()` + and `describe_refresh_shortfall()`. + ### Fixed - The web preview and `/api/v3/display/current` no longer stay black for a diff --git a/docs/SCROLL_PERFORMANCE.md b/docs/SCROLL_PERFORMANCE.md index 4c44865a..c980126b 100644 --- a/docs/SCROLL_PERFORMANCE.md +++ b/docs/SCROLL_PERFORMANCE.md @@ -77,6 +77,31 @@ The Vegas **Scroll Speed** slider in the web UI shows the same thing live: a line under it says what your speed will run as on this panel, and links to the nearest smooth speeds. +### A panel that cannot reach its cap + +Speeds are solved against `limit_refresh_rate_hz`, the configured cap, but a +cap is only a ceiling: a long chain, a high `pwm_bits` or a big +`gpio_slowdown` can leave the panel below it. One Pi 4 driving 2×128×64 on +`adafruit-hat-pwm` with `pwm_bits 9` and `gpio_slowdown 5` measured +107.6–113.1 Hz under a 120 Hz cap. Frames still move whole pixels, but +every scroll runs that much slower than configured (60 px/s ran at 55 px/s), +and the smooth speeds are the cap's rather than the panel's. + +The display measures the real rate from its own frames. About a minute +into scrolling, a panel more than 3% short of its cap is logged once: + +``` +WARNING - src.common.frame_timing - The panel refreshes at about 113 Hz, below +the 120 Hz that scroll speeds are planned for ... Set Limit Refresh Rate to +100 Hz (web UI, Display tab), which this panel can hold, and restart. +``` + +The Display tab says the same under **Limit Refresh Rate**, with a button +that fills in the suggested cap (`GET /api/v3/config/refresh-rate`). The +suggestion is a multiple of 10 at least 5% under the measurement, because +an uncapped panel drifts and the measurement is the fast end of it. A cap the +panel holds also stops the drift. + ### How a slow speed stays crisp `SwapOnVSync(canvas, framerate_fraction)` holds each frame for N panel diff --git a/src/common/frame_timing.py b/src/common/frame_timing.py index 4c0edbdc..4304b107 100644 --- a/src/common/frame_timing.py +++ b/src/common/frame_timing.py @@ -135,6 +135,8 @@ import time import traceback from typing import Any, Callable, Dict, List, Optional, Tuple, TypedDict +from src.common import scroll_config + logger = logging.getLogger(__name__) #: Bumped when a field changes meaning, so a reader can refuse stale files. @@ -179,6 +181,12 @@ MAX_REFRESH_DROP = 0.2 #: trusted -- about a second of scrolling. MIN_FRAMES_FOR_REFRESH = 90 +#: Trusted windows, counting the one that adopted the period, before a panel +#: slower than its cap is reported. The estimate can still fall (the refresh +#: rate rise) by up to MAX_REFRESH_DROP per window early on; the warning +#: should not name a rate one more window would have corrected. +REFRESH_CHECK_WINDOWS = 3 + FLUSH_INTERVAL = 10.0 #: A scroll's last frame older than this is a stall worth a stack dump. @@ -441,6 +449,12 @@ class FrameTimingRecorder: 1.0 / refresh_hz if refresh_hz and refresh_hz > 0 else None) # The first estimate, until a second window agrees with it. self._refresh_candidate: Optional[float] = None + # The rate scroll speeds are solved against; see plan_refresh(). + self.planned_refresh_hz: Optional[float] = None + # Trusted windows seen since the period was adopted, until the + # shortfall check has run. + self._refresh_windows = 0 + self._shortfall_checked = True self.totals: Dict[str, Any] = { "static_frames": 0, "scroll_frames": 0, @@ -639,7 +653,12 @@ class FrameTimingRecorder: self._refresh_candidate = estimate elif current * (1.0 - MAX_REFRESH_DROP) <= estimate < current: self.refresh_period = estimate + if self.refresh_period is not None: + self._refresh_windows += 1 period = self.refresh_period + if (period and not self._shortfall_checked + and self._refresh_windows >= REFRESH_CHECK_WINDOWS): + self._check_refresh_shortfall(1.0 / period) histograms = self.histograms for frame in batch: @@ -688,6 +707,25 @@ class FrameTimingRecorder: elif missed <= -1: totals["early_frames"] += 1 + def plan_refresh(self, hz: Optional[float]) -> None: + """Say what rate scroll speeds are solved against, before frames arrive. + + ``DisplayManager.refresh_hz``: the configured cap. Once the measured + rate has held for :data:`REFRESH_CHECK_WINDOWS` windows, a panel that + falls short of it is logged once, with a cap it can hold (see + :func:`src.common.scroll_config.refresh_shortfall`). The display + manager calls this only for a real panel. + """ + self.planned_refresh_hz = hz + self._shortfall_checked = not hz + + def _check_refresh_shortfall(self, measured_hz: float) -> None: + """Log, once, a panel that cannot reach the rate speeds assume.""" + self._shortfall_checked = True + shortfall = scroll_config.refresh_shortfall(measured_hz, self.planned_refresh_hz) + if shortfall: + logger.warning(scroll_config.describe_refresh_shortfall(shortfall)) + def snapshot(self) -> Dict[str, Any]: """The JSON document: cumulative since this process started.""" if not self._binding_checked: @@ -704,6 +742,9 @@ class FrameTimingRecorder: "bucket_ms": BUCKET_MS, "freeze_seconds": FREEZE_SECONDS, "measured_refresh_hz": round(1.0 / period, 2) if period else None, + # Additive: what scroll speeds were solved against, so a reader can + # tell a stale file (written under another cap) from this one. + "planned_refresh_hz": self.planned_refresh_hz, "binding_releases_gil": self._binding_gil, "info": info, "totals": copy.deepcopy(self.totals), diff --git a/src/common/scroll_config.py b/src/common/scroll_config.py index f45acca1..8d3dc026 100644 --- a/src/common/scroll_config.py +++ b/src/common/scroll_config.py @@ -538,3 +538,66 @@ def speed_advice( "smooth": smooth, "alternatives": [as_dict(c) for c in alternatives], } + + +#: A measured refresh this far below the rate speeds are planned for means +#: the panel cannot reach its cap. Smaller gaps are the cap's own slack and +#: the estimate's: one rig measured 99.95 Hz under a 100 Hz cap. +REFRESH_SHORTFALL = 0.03 + +#: How far under the measured rate a suggested cap sits. The measurement is +#: the fast end of the panel's refreshes (frame_timing takes the 10th +#: percentile of intervals), and an uncapped panel drifts: one read +#: 107.6-113.1 Hz over 15 seconds. A cap inside that band would not hold. +CAP_HEADROOM = 0.05 + + +def holdable_cap(measured_hz: Any) -> Optional[int]: + """A refresh cap the panel can hold: a multiple of 10, 5% under what it measured. + + A multiple of 10 because its whole-pixel speeds are round numbers (a + 100 Hz cap gives 50 and 100 px/s). None without a usable measurement, or + when the panel is too slow for any cap of 10 Hz or more. + """ + hz = _coerce(measured_hz) + if hz is None: + return None + cap = int(hz * (1.0 - CAP_HEADROOM) // 10) * 10 + return cap if cap >= 10 else None + + +def refresh_shortfall(measured_hz: Any, planned_hz: Any) -> Optional[Dict[str, Any]]: + """When the panel refreshes measurably slower than speeds are planned for. + + ``planned_hz`` is what :func:`configure` solves against -- the + ``limit_refresh_rate_hz`` cap, or :data:`DEFAULT_REFRESH_HZ` when it is 0. + A panel that cannot reach it still moves whole pixels per frame, but every + speed runs slow by the shortfall and the ladder of smooth speeds is the + cap's, not the panel's. None when there is no measurement, or the panel + reaches the cap (or beats it, as some do by a few Hz). + """ + measured, planned = _coerce(measured_hz), _coerce(planned_hz) + if measured is None or planned is None: + return None + if measured >= planned * (1.0 - REFRESH_SHORTFALL): + return None + return { + "measured_hz": round(measured, 1), + "planned_hz": round(planned, 1), + "suggested_cap_hz": holdable_cap(measured), + "slow_percent": round((1.0 - measured / planned) * 100), + } + + +def describe_refresh_shortfall(shortfall: Dict[str, Any]) -> str: + """One log line for :func:`refresh_shortfall`'s answer.""" + text = ( + f"The panel refreshes at about {shortfall['measured_hz']:.0f} Hz, below " + f"the {shortfall['planned_hz']:.0f} Hz that scroll speeds are planned " + f"for (display.hardware.limit_refresh_rate_hz), so every scroll runs " + f"about {shortfall['slow_percent']}% slower than configured and the " + f"smooth speeds are worked out for a rate this panel never reaches.") + if shortfall.get("suggested_cap_hz"): + text += (f" Set Limit Refresh Rate to {shortfall['suggested_cap_hz']} Hz " + f"(web UI, Display tab), which this panel can hold, and restart.") + return text diff --git a/src/display_manager.py b/src/display_manager.py index 05b04cb7..dcf3c284 100644 --- a/src/display_manager.py +++ b/src/display_manager.py @@ -393,6 +393,11 @@ class DisplayManager: self._setup_matrix() logger.info("Matrix setup completed in %.3f seconds", time.time() - start_time) + # Only a real panel's swaps wait on its refresh: the emulator and the + # fallback canvas pace themselves, so "slower than the cap" would be + # noise there. + if self.matrix is not None and os.environ.get('EMULATOR', 'false') != 'true': + self.frame_timing.plan_refresh(self.refresh_hz) self._setup_scan_order_compensation() font_time = time.time() @@ -1501,7 +1506,9 @@ class DisplayManager: fractional-pixel motion. See src/common/scroll_config.py. Note this is the configured *cap*, not necessarily what the panel - achieves -- scripts/scroll_speeds.py --measure reports the real rate. + achieves -- scripts/scroll_speeds.py --measure reports the real rate, + and the frame-timing recorder logs a warning, with a cap the panel can + hold, once it has measured a panel that falls short of this. """ hardware = (self.config.get('display') or {}).get('hardware') or {} try: diff --git a/test/fixtures/api_v3_url_map.json b/test/fixtures/api_v3_url_map.json index 707c8774..7beb1c09 100644 --- a/test/fixtures/api_v3_url_map.json +++ b/test/fixtures/api_v3_url_map.json @@ -175,6 +175,15 @@ "POST" ] ], + [ + "/api/v3/config/refresh-rate", + "api_v3.get_refresh_rate", + [ + "GET", + "HEAD", + "OPTIONS" + ] + ], [ "/api/v3/config/schedule", "api_v3.get_schedule_config", diff --git a/test/test_frame_timing.py b/test/test_frame_timing.py index e6610ddf..6a25fbe1 100644 --- a/test/test_frame_timing.py +++ b/test/test_frame_timing.py @@ -807,3 +807,54 @@ def test_a_process_with_the_gc_monitor_exits_cleanly(): assert proc.returncode == 0, proc.stderr assert "Exception ignored" not in proc.stderr assert "installed at exit: False" in proc.stdout + + +SLOW = 1 / 110.0 # a panel that cannot reach a 120 Hz cap + + +def _windows(recorder, n, interval, start=0.0): + for i in range(n): + _feed(recorder, [interval] * 200, start=start + 50.0 * i) + _aggregate(recorder) + + +def _shortfall_warnings(caplog): + return [r for r in caplog.records + if r.name == "src.common.frame_timing" and "Limit Refresh Rate" in r.getMessage()] + + +def test_a_panel_slower_than_its_cap_is_reported_once(tmp_path, caplog): + r = _recorder(tmp_path) + r.plan_refresh(120.0) + caplog.set_level("WARNING") + _windows(r, 3, SLOW) # adopted on the 2nd window, checked on the 4th + assert _shortfall_warnings(caplog) == [] + _windows(r, 3, SLOW, start=1000.0) + warnings = _shortfall_warnings(caplog) + assert len(warnings) == 1 + assert "about 110 Hz" in warnings[0].getMessage() + assert "to 100 Hz" in warnings[0].getMessage() + + +def test_a_panel_that_reaches_its_cap_is_not_reported(tmp_path, caplog): + r = _recorder(tmp_path) + r.plan_refresh(100.0) + caplog.set_level("WARNING") + _windows(r, 6, PERIOD) + assert _shortfall_warnings(caplog) == [] + + +def test_without_a_planned_rate_nothing_is_checked(tmp_path, caplog): + # The emulator and the fallback canvas: DisplayManager never calls + # plan_refresh(), since their frames are not paced by a panel. + r = _recorder(tmp_path) + caplog.set_level("WARNING") + _windows(r, 6, SLOW) + assert _shortfall_warnings(caplog) == [] + + +def test_the_snapshot_records_the_planned_rate(tmp_path): + r = _recorder(tmp_path) + assert r.snapshot()["planned_refresh_hz"] is None + r.plan_refresh(120.0) + assert r.snapshot()["planned_refresh_hz"] == 120.0 diff --git a/test/test_scroll_config.py b/test/test_scroll_config.py index b3c143ca..e14047ff 100644 --- a/test/test_scroll_config.py +++ b/test/test_scroll_config.py @@ -21,6 +21,7 @@ from src.common.scroll_config import ( # noqa: E402 refresh_hz_from_config, resolve, ) +from src.common import scroll_config # noqa: E402 class FakeHelper: @@ -504,3 +505,46 @@ class TestSpeedAdvice: got = solve_crisp(50, 125.74) assert got.steppiness == "smooth" assert got.pixels_per_frame == 1 + + +class TestRefreshShortfall: + """A panel that cannot reach its cap runs every scroll slow.""" + + def test_the_ledmatrix_rig_is_told_to_cap_at_100(self): + # Pi 4, 2x128x64 on adafruit-hat-pwm under a 120 Hz cap: measured + # 107.6-113.1 Hz, and frame_timing reports the fast end. + s = scroll_config.refresh_shortfall(113.1, 120) + assert s == {"measured_hz": 113.1, "planned_hz": 120.0, + "suggested_cap_hz": 100, "slow_percent": 6} + + def test_a_panel_that_holds_its_cap_is_fine(self): + assert scroll_config.refresh_shortfall(99.95, 100) is None + assert scroll_config.refresh_shortfall(97.5, 100) is None + + def test_a_panel_that_beats_its_cap_is_fine(self): + assert scroll_config.refresh_shortfall(125.7, 120) is None + + def test_nothing_measured_says_nothing(self): + assert scroll_config.refresh_shortfall(None, 120) is None + assert scroll_config.refresh_shortfall(0, 120) is None + assert scroll_config.refresh_shortfall("fast", 120) is None + + def test_the_suggestion_leaves_headroom_under_the_measurement(self): + assert scroll_config.holdable_cap(113.1) == 100 + assert scroll_config.holdable_cap(95.0) == 90 + # 5% under 105 is 99.75: 100 would sit inside the panel's drift. + assert scroll_config.holdable_cap(105.0) == 90 + assert scroll_config.holdable_cap(9.0) is None + assert scroll_config.holdable_cap(None) is None + + def test_the_log_line_names_the_cap_to_use(self): + text = scroll_config.describe_refresh_shortfall( + scroll_config.refresh_shortfall(113.1, 120)) + assert "about 113 Hz" in text and "120 Hz" in text + assert "6% slower" in text + assert "Set Limit Refresh Rate to 100 Hz" in text + + def test_no_suggestion_for_a_panel_too_slow_for_any_cap(self): + text = scroll_config.describe_refresh_shortfall( + scroll_config.refresh_shortfall(9.0, 100)) + assert "Set Limit Refresh Rate" not in text diff --git a/test/web_interface/test_api_v3_refresh_rate.py b/test/web_interface/test_api_v3_refresh_rate.py new file mode 100644 index 00000000..4f3fb226 --- /dev/null +++ b/test/web_interface/test_api_v3_refresh_rate.py @@ -0,0 +1,63 @@ +"""GET /api/v3/config/refresh-rate: the cap, the measured rate, a cap to hold.""" +import json +from unittest.mock import MagicMock + +import pytest +from flask import Flask + +from web_interface.blueprints.api_v3 import api_v3 + + +@pytest.fixture +def client(monkeypatch, tmp_path): + stats = tmp_path / "stats.json" + monkeypatch.setattr("src.common.frame_timing.default_stats_path", lambda: str(stats)) + manager = MagicMock() + manager.load_config.return_value = { + "display": {"hardware": {"limit_refresh_rate_hz": 120}}} + monkeypatch.setattr(api_v3, "config_manager", manager, raising=False) + app = Flask(__name__) + app.register_blueprint(api_v3, url_prefix="/api/v3") + c = app.test_client() + c.stats_path = stats + return c + + +def _get(client): + body = client.get("/api/v3/config/refresh-rate").get_json() + assert body["status"] == "success" + return body["data"] + + +def test_nothing_measured_yet(client): + data = _get(client) + assert data == {"planned_hz": 120.0, "measured_hz": None, "shortfall": None} + + +def test_a_panel_short_of_its_cap_gets_a_cap_it_can_hold(client): + client.stats_path.write_text(json.dumps( + {"measured_refresh_hz": 110.4, "planned_refresh_hz": 120.0})) + data = _get(client) + assert data["measured_hz"] == 110.4 + assert data["shortfall"]["suggested_cap_hz"] == 100 + assert data["shortfall"]["slow_percent"] == 8 + + +def test_a_panel_at_its_cap_has_no_shortfall(client): + client.stats_path.write_text(json.dumps( + {"measured_refresh_hz": 121.3, "planned_refresh_hz": 120.0})) + assert _get(client)["shortfall"] is None + + +def test_a_file_written_under_another_cap_is_stale(client): + # The cap was changed to 120 but the display still runs under 100 Hz. + client.stats_path.write_text(json.dumps( + {"measured_refresh_hz": 99.9, "planned_refresh_hz": 100.0})) + data = _get(client) + assert data["measured_hz"] is None + assert data["shortfall"] is None + + +def test_a_file_from_a_display_too_old_to_record_its_cap_still_counts(client): + client.stats_path.write_text(json.dumps({"measured_refresh_hz": 110.4})) + assert _get(client)["shortfall"]["suggested_cap_hz"] == 100 diff --git a/web_interface/blueprints/api_v3/config.py b/web_interface/blueprints/api_v3/config.py index 91ee73ba..f7f7fe9b 100644 --- a/web_interface/blueprints/api_v3/config.py +++ b/web_interface/blueprints/api_v3/config.py @@ -158,11 +158,16 @@ def _panel_refresh_hz(config): cap = scroll_config.refresh_hz_from_config(config) try: with open(frame_timing.default_stats_path(), encoding='utf-8') as fh: - measured = float(json.load(fh).get('measured_refresh_hz') or 0) + stats = json.load(fh) + measured = float(stats.get('measured_refresh_hz') or 0) + planned = float(stats.get('planned_refresh_hz') or 0) except (OSError, ValueError, TypeError, AttributeError): + measured = planned = 0.0 + # Reject a stale file from a previous hardware config: one written under + # another cap (the display has not restarted since it changed), or, from + # a display too old to record its cap, a measurement far off this one. + if planned and abs(planned - cap) > 0.5: measured = 0.0 - # Reject a stale file from a previous hardware config: a measurement far - # off the cap says the config changed since it was written. if measured > 0 and 0.5 * cap <= measured <= 1.5 * cap: return measured, 'measured' return cap, 'configured' @@ -189,6 +194,29 @@ def get_scroll_speed_advice(): return jsonify({'status': 'success', 'data': advice}) +@api_v3.route('/config/refresh-rate', methods=['GET']) +def get_refresh_rate(): + """The refresh cap, what the panel measured, and a cap it can hold. + + Backs the hint under the Display tab's Limit Refresh Rate field. Scroll + speeds are solved against the cap, so a panel that cannot reach it runs + every scroll slow; ``shortfall`` (None when the panel keeps up, or nothing + has been measured yet) says by how much and suggests a cap. + """ + from src.common import scroll_config + if not api_v3.config_manager: + return jsonify({'status': 'error', 'message': 'Config manager not initialized'}), 500 + config = api_v3.config_manager.load_config() + planned = scroll_config.refresh_hz_from_config(config) + hz, source = _panel_refresh_hz(config) + measured = hz if source == 'measured' else None + return jsonify({'status': 'success', 'data': { + 'planned_hz': planned, + 'measured_hz': round(measured, 1) if measured else None, + 'shortfall': scroll_config.refresh_shortfall(measured, planned), + }}) + + @api_v3.route('/config/schedule', methods=['GET']) def get_schedule_config(): """Get current schedule configuration""" diff --git a/web_interface/templates/v3/partials/display.html b/web_interface/templates/v3/partials/display.html index 8cff6911..9ddc8651 100644 --- a/web_interface/templates/v3/partials/display.html +++ b/web_interface/templates/v3/partials/display.html @@ -318,6 +318,7 @@ min="0" max="1000" class="form-control"> +

@@ -915,6 +916,41 @@ document.getElementById('brightness').addEventListener('input', function() { }); } + // Say so when the panel cannot reach its refresh cap. Scroll speeds are + // worked out against the cap, so every scroll then runs slow, and the + // display has measured a cap the panel can hold. + (function refreshRateHint() { + const hint = document.getElementById('limit_refresh_rate_hz_hint'); + const input = document.getElementById('limit_refresh_rate_hz'); + if (!hint || !input) return; + fetch('/api/v3/config/refresh-rate') + .then(function(r) { return r.json(); }) + .then(function(body) { + const s = body.status === 'success' && body.data.shortfall; + hint.textContent = ''; + if (!s) return; + hint.appendChild(document.createTextNode( + 'This panel refreshes at about ' + Math.round(s.measured_hz) + + ' Hz, below this ' + Math.round(s.planned_hz) + ' Hz cap, so scrolls run about ' + + s.slow_percent + '% slower than set.' + (s.suggested_cap_hz ? ' ' : ''))); + if (!s.suggested_cap_hz) return; + const btn = document.createElement('button'); + btn.type = 'button'; + btn.className = 'underline font-medium'; + btn.textContent = 'Use ' + s.suggested_cap_hz + ' Hz'; + btn.addEventListener('click', function() { + input.value = s.suggested_cap_hz; + input.dispatchEvent(new Event('input', {bubbles: true})); + input.dispatchEvent(new Event('change', {bubbles: true})); + hint.textContent = 'Save, then restart the display, to apply ' + + s.suggested_cap_hz + ' Hz.'; + }); + hint.appendChild(btn); + hint.appendChild(document.createTextNode(', a cap it can hold.')); + }) + .catch(function() { hint.textContent = ''; }); + })(); + // Declared before first use: let is not hoisted usably. let scrollHintTimer = null; let scrollHintSeq = 0;