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)
# The image already includes display_width padding, so we only need 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%%)",
elapsed_time,
self.calculated_duration,
+37 -7
View File
@@ -31,6 +31,14 @@ if TYPE_CHECKING:
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:
"""Nearest-rank percentile of an already-sorted list.
@@ -395,7 +403,9 @@ class VegasModeCoordinator:
duration = self.render_pipeline.get_dynamic_duration()
start_time = time.time()
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
fps_frame_count = 0
# A mean hides stutter completely. At 120fps a five-second window is
@@ -448,16 +458,36 @@ class VegasModeCoordinator:
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()
if current_time - last_fps_log_time >= fps_log_interval:
fps = fps_frame_count / (current_time - last_fps_log_time)
p99 = _percentile(sorted(frame_times), 0.99)
logger.info(
"Vegas FPS: %.1f (target: %d, frames: %d) p99 %.1fms worst %.1fms",
fps, self.vegas_config.target_fps, fps_frame_count,
p99 * 1000.0, frame_worst * 1000.0
)
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(
"Vegas FPS: %.1f (target: %d, frames: %d) p99 %.1fms worst %.1fms",
fps, target, fps_frame_count,
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
fps_frame_count = 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):
args, note, error = resolve_pull_command(str(repos))
assert error is None
assert args == ['git', 'pull', '--rebase', '--autostash']
assert args == ['git', 'pull', '--rebase']
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))
assert error is None
assert args == ['git', 'pull', '--rebase', '--autostash', 'origin', 'audit']
assert args == ['git', 'pull', '--rebase', 'origin', 'audit']
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))
assert error is None
assert args == ['git', 'pull', '--rebase', '--autostash']
assert args == ['git', 'pull', '--rebase']
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'
# The edit is not lost — it is on the stash.
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
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
is made explicit against it, so the update proceeds and the branch is
given tracking information afterwards.
"""
upstream = _git_upstream(project_dir)
if upstream:
return ['git', 'pull', '--rebase', '--autostash'], '', None
return ['git', 'pull', '--rebase'], '', None
branch = _git_current_branch(project_dir)
if not branch:
@@ -1682,7 +1673,7 @@ def resolve_pull_command(project_dir):
)
if _git_remote_branch_exists(project_dir, branch):
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.",
None,
)