diff --git a/src/vegas_mode/coordinator.py b/src/vegas_mode/coordinator.py index e75e8c51..cd7fd70a 100644 --- a/src/vegas_mode/coordinator.py +++ b/src/vegas_mode/coordinator.py @@ -12,6 +12,7 @@ Supports three display modes per plugin: """ import logging +import math import time import threading from typing import Optional, Dict, Any, List, Callable, TYPE_CHECKING @@ -30,6 +31,21 @@ if TYPE_CHECKING: logger = logging.getLogger(__name__) +def _percentile(ordered: List[float], fraction: float) -> float: + """Nearest-rank percentile of an already-sorted list. + + Index ceil(n * fraction) - 1, so 100 samples at 0.99 give the 99th-ranked + value. The obvious int(n * fraction) is off by one and, at exactly 100 + samples, lands on the maximum -- which is the number already reported + alongside this one as the worst frame, so the two columns would agree + precisely when the sample was smallest. + """ + if not ordered: + return 0.0 + index = math.ceil(len(ordered) * fraction) - 1 + return ordered[min(len(ordered) - 1, max(0, index))] + + class VegasModeCoordinator: """ Orchestrates Vegas scroll mode operation. @@ -382,6 +398,12 @@ class VegasModeCoordinator: fps_log_interval = 5.0 # Log FPS every 5 seconds last_fps_log_time = start_time fps_frame_count = 0 + # A mean hides stutter completely. At 120fps a five-second window is + # ~600 frames, so a 200ms freeze -- plainly visible on a marquee -- + # moves the average from 120.0 to 115.4 and reads as healthy. What a + # viewer actually notices is the worst frame, so track that too. + frame_worst = 0.0 + frame_times: List[float] = [] logger.info("Starting Vegas iteration for %.1fs", duration) @@ -417,6 +439,11 @@ class VegasModeCoordinator: frame_elapsed = time.time() - frame_started time.sleep(max(0.0, frame_interval - frame_elapsed)) + # Measured before the sleep: time spent working, not pacing. + if frame_elapsed > frame_worst: + frame_worst = frame_elapsed + frame_times.append(frame_elapsed) + # Increment frame count and check for interrupt periodically frame_count += 1 fps_frame_count += 1 @@ -425,12 +452,16 @@ class VegasModeCoordinator: 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)", - fps, self.vegas_config.target_fps, fps_frame_count + "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 ) last_fps_log_time = current_time fps_frame_count = 0 + frame_worst = 0.0 + frame_times.clear() if (self._interrupt_check and frame_count % self._interrupt_check_interval == 0): diff --git a/test/test_vegas_frame_percentile.py b/test/test_vegas_frame_percentile.py new file mode 100644 index 00000000..581ca2a9 --- /dev/null +++ b/test/test_vegas_frame_percentile.py @@ -0,0 +1,64 @@ +"""Tests the percentile used by the Vegas frame-time log line. + +The FPS line reports p99 next to the worst frame, and the point of having both +is that they say different things: p99 is the bad-but-ordinary frame, worst is +the outlier. The obvious index, int(n * 0.99), is off by one and at exactly +100 samples selects the maximum -- so the two columns would report the same +number precisely when the sample was smallest. +""" + +import math + +import pytest + +from src.vegas_mode.coordinator import _percentile + + +class TestNearestRank: + def test_a_hundred_samples_do_not_return_the_maximum(self): + ordered = [float(i) for i in range(100)] # 0..99 + assert _percentile(ordered, 0.99) == 98.0 + assert _percentile(ordered, 0.99) != max(ordered) + + def test_it_matches_the_nearest_rank_definition(self): + for n in (1, 2, 3, 10, 99, 100, 101, 600, 1000): + ordered = [float(i) for i in range(n)] + expected = ordered[min(n - 1, max(0, math.ceil(n * 0.99) - 1))] + assert _percentile(ordered, 0.99) == expected, n + + @pytest.mark.parametrize('fraction,expected', [ + (0.0, 0.0), # first + (0.5, 49.0), # median, nearest-rank + (1.0, 99.0), # last + ]) + def test_other_fractions(self, fraction, expected): + assert _percentile([float(i) for i in range(100)], fraction) == expected + + +class TestEdges: + def test_empty_is_zero_not_an_error(self): + # The loop calls this before any frame has been timed. + assert _percentile([], 0.99) == 0.0 + + def test_a_single_sample_is_itself(self): + assert _percentile([4.2], 0.99) == 4.2 + + def test_it_never_indexes_past_the_end(self): + for n in range(1, 50): + _percentile([float(i) for i in range(n)], 1.0) # must not raise + + +class TestItSaysSomethingUsefulAboutFrames: + def test_one_freeze_does_not_drag_p99_up(self): + # 599 healthy frames and one 3.2s freeze: p99 should still describe + # the healthy population, while the worst frame is reported separately. + frames = [0.0083] * 599 + [3.2] + p99 = _percentile(sorted(frames), 0.99) + assert p99 == pytest.approx(0.0083), p99 + assert max(frames) == 3.2 + + def test_sustained_slowness_does_move_it(self): + # Ten percent of frames slow is not an outlier, it is the shape of the + # distribution, and p99 must reflect that. + frames = [0.0083] * 540 + [0.05] * 60 + assert _percentile(sorted(frames), 0.99) == pytest.approx(0.05)