Compare commits

..
Author SHA1 Message Date
ChuckBuildsandClaude Opus 5 a4290e8a28 perf(vegas): report the frame rate when it is worth reporting
Two Vegas telemetry lines were 37% of a running rig's entire log volume:
"Vegas FPS" every five seconds and "Scroll progress" on its own five-second
timer, 712 lines in half an hour, every one a journal write to an SD card.

The FPS line is the interesting one, because almost none of it was news.
Measured over two hours on that rig: 1410 samples, 98.5% of them within 10%
of target. What the other 1.5% contained was a reading of 8.6fps against a
target of 60 -- a real stall, sitting invisible inside 1389 lines that read
"59.6".

So it now reports at INFO when the frame rate falls short of target, when it
recovers from a shortfall, and on a five-minute heartbeat so a healthy
marquee still shows a pulse. Everything else drops to debug.

Replaying the same two hours of real samples through the committed logic:
1410 -> 53 INFO lines, a 96% reduction, and all 21 degraded samples are
retained, worst reading included. The signal survives; the wall of "fine"
does not.

Scroll progress is demoted outright. It reports how far along a marquee is,
which is what you turn debug on to watch, not something an operator needs in
the journal on a device that scrolls all day.

543 vegas and scroll tests pass.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01STMbQE4YctTacQXfbYqKuW
2026-08-20 20:26:34 -04:00
11 changed files with 47 additions and 56 deletions
Binary file not shown.

After

Width:  |  Height:  |  Size: 76 KiB

Binary file not shown.

After

Width:  |  Height:  |  Size: 128 KiB

Executable → Regular
View File
View File
View File
+5 -1
View File
@@ -328,7 +328,11 @@ class ScrollHelper:
elapsed_time = current_time - (self.scroll_start_time or current_time) elapsed_time = current_time - (self.scroll_start_time or current_time)
# The image already includes display_width padding, so we only need total_scroll_width # The image already includes display_width padding, so we only need total_scroll_width
required_total_distance = self.total_scroll_width required_total_distance = self.total_scroll_width
self.logger.info( # Progress telemetry, emitted every few seconds for the whole of
# every scroll. It says how far along a marquee is, which is what
# you turn debug on to watch and not something an operator needs
# in the journal on a device that scrolls all day.
self.logger.debug(
"Scroll progress: elapsed=%.2fs, target=%.2fs, total_scrolled=%.0f/%d px (%.1f%%)", "Scroll progress: elapsed=%.2fs, target=%.2fs, total_scrolled=%.0f/%d px (%.1f%%)",
elapsed_time, elapsed_time,
self.calculated_duration, self.calculated_duration,
+33 -3
View File
@@ -31,6 +31,14 @@ if TYPE_CHECKING:
logger = logging.getLogger(__name__) logger = logging.getLogger(__name__)
#: A frame rate this close to target is not news; below it is.
_FPS_HEALTHY_FRACTION = 0.9
#: A healthy marquee still reports this often, so silence means stopped
#: rather than fine.
_FPS_HEARTBEAT_INTERVAL = 300.0
def _percentile(ordered: List[float], fraction: float) -> float: def _percentile(ordered: List[float], fraction: float) -> float:
"""Nearest-rank percentile of an already-sorted list. """Nearest-rank percentile of an already-sorted list.
@@ -395,7 +403,9 @@ class VegasModeCoordinator:
duration = self.render_pipeline.get_dynamic_duration() duration = self.render_pipeline.get_dynamic_duration()
start_time = time.time() start_time = time.time()
frame_count = 0 frame_count = 0
fps_log_interval = 5.0 # Log FPS every 5 seconds fps_log_interval = 5.0 # Sample FPS every 5 seconds
last_fps_health_log = 0.0 # last INFO-level report
was_degraded = False # so the recovery is reported too
last_fps_log_time = start_time last_fps_log_time = start_time
fps_frame_count = 0 fps_frame_count = 0
# A mean hides stutter completely. At 120fps a five-second window is # A mean hides stutter completely. At 120fps a five-second window is
@@ -448,16 +458,36 @@ class VegasModeCoordinator:
frame_count += 1 frame_count += 1
fps_frame_count += 1 fps_frame_count += 1
# Periodic FPS logging # Periodic FPS logging. Reported at INFO only when the frame rate
# is actually worth an operator's attention -- a shortfall against
# target, or the recovery from one -- with a slow heartbeat so a
# healthy marquee still shows a pulse.
#
# Measured over two hours on a running rig: 1410 samples, 98.5%
# of them within 10% of target. The 1.5% that were not included a
# reading of 8.6fps against a target of 60 -- a real stall, and
# completely invisible inside 1389 lines reading "59.6".
current_time = time.time() current_time = time.time()
if current_time - last_fps_log_time >= fps_log_interval: if current_time - last_fps_log_time >= fps_log_interval:
fps = fps_frame_count / (current_time - last_fps_log_time) fps = fps_frame_count / (current_time - last_fps_log_time)
p99 = _percentile(sorted(frame_times), 0.99) p99 = _percentile(sorted(frame_times), 0.99)
target = self.vegas_config.target_fps
degraded = target > 0 and fps < target * _FPS_HEALTHY_FRACTION
due = current_time - last_fps_health_log >= _FPS_HEARTBEAT_INTERVAL
if degraded or was_degraded or due:
logger.info( logger.info(
"Vegas FPS: %.1f (target: %d, frames: %d) p99 %.1fms worst %.1fms", "Vegas FPS: %.1f (target: %d, frames: %d) p99 %.1fms worst %.1fms",
fps, self.vegas_config.target_fps, fps_frame_count, fps, target, fps_frame_count,
p99 * 1000.0, frame_worst * 1000.0 p99 * 1000.0, frame_worst * 1000.0
) )
last_fps_health_log = current_time
else:
logger.debug(
"Vegas FPS: %.1f (target: %d, frames: %d) p99 %.1fms worst %.1fms",
fps, target, fps_frame_count,
p99 * 1000.0, frame_worst * 1000.0
)
was_degraded = degraded
last_fps_log_time = current_time last_fps_log_time = current_time
fps_frame_count = 0 fps_frame_count = 0
frame_worst = 0.0 frame_worst = 0.0
Executable → Regular
View File
Executable → Regular
View File
+3 -37
View File
@@ -58,7 +58,7 @@ def repos(tmp_path):
def test_branch_with_upstream_uses_a_plain_pull(repos): def test_branch_with_upstream_uses_a_plain_pull(repos):
args, note, error = resolve_pull_command(str(repos)) args, note, error = resolve_pull_command(str(repos))
assert error is None assert error is None
assert args == ['git', 'pull', '--rebase', '--autostash'] assert args == ['git', 'pull', '--rebase']
assert note == '' assert note == ''
@@ -73,7 +73,7 @@ def test_branch_without_upstream_falls_back_to_origin_branch(repos):
args, note, error = resolve_pull_command(str(repos)) args, note, error = resolve_pull_command(str(repos))
assert error is None assert error is None
assert args == ['git', 'pull', '--rebase', '--autostash', 'origin', 'audit'] assert args == ['git', 'pull', '--rebase', 'origin', 'audit']
assert 'audit' in note assert 'audit' in note
@@ -155,7 +155,7 @@ def test_switching_attaches_tracking_so_pull_needs_no_fallback(repos):
args, note, error = resolve_pull_command(str(repos)) args, note, error = resolve_pull_command(str(repos))
assert error is None assert error is None
assert args == ['git', 'pull', '--rebase', '--autostash'] assert args == ['git', 'pull', '--rebase']
assert note == '' assert note == ''
@@ -200,37 +200,3 @@ def test_stash_option_lets_the_switch_through_and_keeps_the_work(repos):
assert _git('branch', '--show-current', cwd=repos).stdout.strip() == 'other' assert _git('branch', '--show-current', cwd=repos).stdout.strip() == 'other'
# The edit is not lost — it is on the stash. # The edit is not lost — it is on the stash.
assert 'switch to other' in _git('stash', 'list', cwd=repos).stdout assert 'switch to other' in _git('stash', 'list', cwd=repos).stdout
class TestInstallerDoesNotBlockTheUpdateButton:
"""first_time_install.sh chmods scripts that git tracked as 644.
With core.fileMode true -- the default on Linux -- that leaves five
permanently modified tracked files on every machine that ran the
installer, and `git pull --rebase` refuses to start:
error: cannot pull with rebase: You have unstaged changes.
Tracking them as executable makes the installer's chmod a no-op.
"""
CHMODDED = [
'first_time_install.sh',
'start_display.sh',
'stop_display.sh',
'scripts/install/install_service.sh',
'scripts/install/install_web_service.sh',
]
def test_scripts_the_installer_chmods_are_tracked_executable(self):
import subprocess
from pathlib import Path
root = Path(__file__).resolve().parent.parent
out = subprocess.run(['git', 'ls-files', '-s', *self.CHMODDED],
capture_output=True, text=True, cwd=str(root)).stdout
modes = {line.split()[3]: line.split()[0] for line in out.strip().split('\n') if line}
non_exec = sorted(f for f, m in modes.items() if m != '100755')
assert not non_exec, (
f"{non_exec} are chmodded by the installer but tracked non-executable, "
"so every install leaves the working tree dirty and the update "
"button cannot pull")
+2 -11
View File
@@ -1657,22 +1657,13 @@ def resolve_pull_command(project_dir):
backup, or following an install guide that names one. The update button backup, or following an install guide that names one. The update button
then reports a failure the user cannot act on. then reports a failure the user cannot act on.
``--autostash`` is passed for the same reason. Rebase refuses to start
when any tracked file is modified, and on these installs something always
is: first_time_install.sh chmods five scripts that git tracked as 644, so
every machine that ran the installer carries five permanent mode changes
and the update button reports "cannot pull with rebase: You have unstaged
changes". Those modes are corrected in this commit, but a user cannot pull
the correction while the pull is what is blocked, and any other local edit
would reproduce it anyway. Autostash reapplies the changes afterwards.
Returns ``(args, note, error)``. When ``origin/<branch>`` exists the pull Returns ``(args, note, error)``. When ``origin/<branch>`` exists the pull
is made explicit against it, so the update proceeds and the branch is is made explicit against it, so the update proceeds and the branch is
given tracking information afterwards. given tracking information afterwards.
""" """
upstream = _git_upstream(project_dir) upstream = _git_upstream(project_dir)
if upstream: if upstream:
return ['git', 'pull', '--rebase', '--autostash'], '', None return ['git', 'pull', '--rebase'], '', None
branch = _git_current_branch(project_dir) branch = _git_current_branch(project_dir)
if not branch: if not branch:
@@ -1682,7 +1673,7 @@ def resolve_pull_command(project_dir):
) )
if _git_remote_branch_exists(project_dir, branch): if _git_remote_branch_exists(project_dir, branch):
return ( return (
['git', 'pull', '--rebase', '--autostash', 'origin', branch], ['git', 'pull', '--rebase', 'origin', branch],
f"Branch '{branch}' had no upstream; pulled from origin/{branch} and set it as the upstream.", f"Branch '{branch}' had no upstream; pulled from origin/{branch} and set it as the upstream.",
None, None,
) )