Add speed-aware playback performance HUD

playback/player.py

@@ -55,6 +55,7 @@
 
 from __future__ import absolute_import
 
+import time
 import numpy
 import threading
 
@@ -81,7 +82,8 @@
 class SequenceDecodeThread(QtCore.QThread):
     """Bounded EXR/image decoder queue modeled after a media decoder FIFO."""
 
-    decoded = QtCore.Signal(int, object, int, str)
+    # frame_number, image, generation, error, decode_milliseconds
+    decoded = QtCore.Signal(int, object, int, str, float)
 
     def __init__(self, parent=None):
         super().__init__(parent)
@@ -147,6 +149,7 @@ def run(self):
             reader, frame_number, aov, processor, generation, _key = task
             error = ""
             image = None
+            started = time.perf_counter()
             try:
                 image = reader.get_frame(
                     frame_number,
@@ -158,7 +161,10 @@ def run(self):
             finally:
                 with self._condition:
                     self._inflight_key = None
-            self.decoded.emit(frame_number, image, generation, error)
+            # Timed here rather than on the GUI thread: this is the decode, and
+            # the queue wait in front of it is not the decoder's fault.
+            decode_ms = (time.perf_counter() - started) * 1000.0
+            self.decoded.emit(frame_number, image, generation, error, decode_ms)
 
 
 class BasePlayer(QtCore.QObject):
@@ -222,6 +228,9 @@ def __init__(self):
         # silently reset the speed while the UI still shows the old value.
         self.playback_speed = constants.DEFAULT_PLAYBACK_SPEED
 
+        # Optional PlaybackStats shared with whichever implementation is live.
+        self.stats = None
+
         # Active OCIO processor
         self.ocio_processor = None
 
@@ -266,6 +275,10 @@ def load(self, path):
 
         self.player.set_speed(self.playback_speed)
 
+        # load() rebuilds the implementation, so the stats object has to be
+        # re-attached or the HUD silently goes dead on the next source.
+        self.player.stats = self.stats
+
         if self.ocio_processor:
             self.player.set_ocio(self.ocio_processor, self.input_space, self.display, self.view)
 
@@ -370,6 +383,12 @@ def set_speed(self, value):
         if self.player and hasattr(self.player, "set_speed"):
             self.player.set_speed(self.playback_speed)
 
+    def set_stats(self, stats):
+        """Attach a PlaybackStats collector (None disables measurement)."""
+        self.stats = stats
+        if self.player is not None:
+            self.player.stats = stats
+
     def set_aov(self, aov):
         """Set active AOV.
 
@@ -473,6 +492,9 @@ def __init__(self):
         # still shows every frame -- it just steps through them faster/slower.
         self.speed = constants.DEFAULT_PLAYBACK_SPEED
 
+        # Optional PlaybackStats, assigned by MediaPlayer when the HUD is on.
+        self.stats = None
+
         # Active AOV
         self.current_aov = "rgb"
 
@@ -959,14 +981,16 @@ def update_frame(self):
             priority=True,
         )
 
-    def _frame_decoded(self, frame_number, frame, generation, error):
+    def _frame_decoded(self, frame_number, frame, generation, error, decode_ms=0.0):
         if generation != self.decode_generation or self.reader is None:
             return
         if error:
             LOGGER.error(f"Sequence frame {frame_number} failed: {error}")
             return
         if frame is None:
             return
+        if self.stats is not None:
+            self.stats.record_decode(decode_ms)
         self.cache.add(frame_number, frame)
         self.cache_changed.emit(self.cache.cached_frames())
         if frame_number == self.display_request_frame:
@@ -1065,6 +1089,9 @@ def __init__(self):
         # Playback speed multiplier, applied to the elapsed playback clock.
         self.speed = constants.DEFAULT_PLAYBACK_SPEED
 
+        # Optional PlaybackStats, assigned by MediaPlayer when the HUD is on.
+        self.stats = None
+
         # Timeline start frame.
         self.start_frame = constants.VL_START_FRAME
 
@@ -1429,6 +1456,7 @@ def display_video(self, current_time):
         # Consume all ready frames, but render only the newest. If decoding or
         # painting falls behind, displaying stale frames makes the lag worse.
         ready_frame = None
+        ready_count = 0
         while self.video_queue:
 
             # Peek at the next decoded frame.
@@ -1446,8 +1474,11 @@ def display_video(self, current_time):
             self.video_queue.popleft()
 
             ready_frame = frame
+            ready_count += 1
 
         if ready_frame is not None:
+            if self.stats is not None and ready_count > 1:
+                self.stats.record_dropped(ready_count - 1)
             self.display_video_frame(ready_frame)
 
     def display_video_frame(self, frame):
@@ -1479,6 +1510,8 @@ def display_video_frame(self, frame):
             ensuring accurate synchronization with playback time.
         """
 
+        started = time.perf_counter()
+
         frame_time = frame.time
         if frame_time is None and frame.pts is not None:
             frame_time = float(frame.pts * self.reader.video_stream.time_base)
@@ -1520,6 +1553,12 @@ def display_video_frame(self, frame):
             min(frame_number, self.start_frame + self.frame_count - 1),
         )
 
+        # The proxy scale, RGB conversion and OCIO transform are what stand
+        # between a decoded packet and the screen, so that is the cost the HUD
+        # reports for movies.
+        if self.stats is not None:
+            self.stats.record_decode((time.perf_counter() - started) * 1000.0)
+
         # Send the image to the viewer.
         self.frame_ready.emit(image)
 

playback/stats.py

@@ -0,0 +1,218 @@
+"""Playback performance measurement for the viewer HUD.
+
+Answers the question a reviewer actually asks when playback feels wrong: *is it
+me, or is it the machine?* A supervisor calling a note on timing needs to know
+they are watching 24 fps and not 17 -- otherwise they are grading the playback,
+not the shot.
+
+Everything here is pure. The clock is injected, so the rolling averages can be
+tested exactly rather than by sleeping and hoping.
+"""
+
+from __future__ import absolute_import
+
+import time
+
+from collections import deque
+
+# Frames are measured over a short trailing window: long enough to be stable,
+# short enough that a stall shows up immediately rather than being averaged away.
+DEFAULT_WINDOW_SECONDS = 1.0
+
+# Decode timings are averaged over a fixed count instead of a time window, so a
+# paused player still reports the cost of the frames it did decode.
+DEFAULT_DECODE_SAMPLES = 30
+
+
+class PlaybackStats(object):
+    """Rolling measurement of displayed frame rate and decode cost.
+
+    Example:
+        >>> stats = PlaybackStats()
+        >>> stats.record_frame()
+        >>> stats.measured_fps()
+    """
+
+    def __init__(self, clock=None, window=DEFAULT_WINDOW_SECONDS,
+                 decode_samples=DEFAULT_DECODE_SAMPLES):
+        # Injected for tests; perf_counter is monotonic, unlike time().
+        self.clock = clock or time.perf_counter
+        self.window = float(window)
+
+        self.frame_times = deque()
+        self.decode_times = deque(maxlen=int(decode_samples))
+
+        self.dropped = 0
+
+        # Total frames seen since the last reset. Distinguishes "playback has
+        # not started" from "playback started and then died" -- both leave the
+        # rolling window empty, but only one of them is a problem.
+        self.frames_seen = 0
+
+    def reset(self):
+        """Forget every measurement (a new source is not the old one's tail)."""
+        self.frame_times.clear()
+        self.decode_times.clear()
+        self.dropped = 0
+        self.frames_seen = 0
+
+    def reset_frame_timing(self):
+        """Start a fresh FPS window without discarding recent decode cost."""
+        self.frame_times.clear()
+        self.frames_seen = 0
+
+    def record_frame(self):
+        """Record that a frame reached the screen."""
+        now = self.clock()
+        self.frame_times.append(now)
+        self.frames_seen += 1
+        self._trim(now)
+
+    def record_decode(self, milliseconds):
+        """Record how long one frame took to decode."""
+        try:
+            value = float(milliseconds)
+        except (TypeError, ValueError):
+            return
+        if value >= 0:
+            self.decode_times.append(value)
+
+    def record_dropped(self, count=1):
+        """Record frames the player had to skip to keep up."""
+        self.dropped += max(0, int(count))
+
+    def _trim(self, now):
+        threshold = now - self.window
+        while self.frame_times and self.frame_times[0] < threshold:
+            self.frame_times.popleft()
+
+    def measured_fps(self):
+        """Return the displayed frame rate over the trailing window.
+
+        Returns 0.0 until two frames have been seen -- one timestamp measures no
+        interval, and reporting a rate from it would be a guess.
+        """
+        self._trim(self.clock())
+
+        if len(self.frame_times) < 2:
+            return 0.0
+
+        span = self.frame_times[-1] - self.frame_times[0]
+        if span <= 0:
+            return 0.0
+
+        # N timestamps bound N-1 intervals.
+        return (len(self.frame_times) - 1) / span
+
+    def average_decode_ms(self):
+        """Return the mean decode time over the recent samples."""
+        if not self.decode_times:
+            return 0.0
+        return sum(self.decode_times) / len(self.decode_times)
+
+    def stalled(self):
+        """True when frames were playing and then stopped arriving entirely.
+
+        A hard stall empties the rolling window, so measured_fps() drops to
+        zero -- the same reading as "nothing has played yet". Without this
+        distinction a total freeze would render as a calm "--", which is exactly
+        the failure the HUD exists to catch.
+        """
+        return self.frames_seen >= 2 and self.measured_fps() <= 0
+
+    def is_realtime(self, target_fps, tolerance=0.95):
+        """True when playback is holding *target_fps* (within tolerance).
+
+        A player that has not shown two frames yet is not failing -- it just has
+        nothing to say -- so it reports True rather than alarming the reviewer.
+        A player that HAS played and then stopped is a different matter: see
+        :meth:`stalled`, which the HUD checks alongside this.
+        """
+        measured = self.measured_fps()
+        if measured <= 0:
+            return True
+
+        try:
+            target = float(target_fps)
+        except (TypeError, ValueError):
+            return True
+
+        if target <= 0:
+            return True
+
+        return measured >= target * tolerance
+
+
+def hud_lines(stats, target_fps=0, playing=False, frame=None, frame_count=None,
+              resolution=None, proxy_label=None, cached=None):
+    """Format the HUD as a list of ``(label, value, ok)`` rows.
+
+    ``ok`` is False only for a genuinely bad reading, so the HUD can colour just
+    that row rather than shouting about everything at once.
+
+    ``playing`` is needed to tell a stall from a pause: both stop frames
+    arriving, but only one of them is a fault.
+    """
+    rows = list()
+
+    measured = stats.measured_fps()
+
+    try:
+        target = float(target_fps or 0)
+    except (TypeError, ValueError):
+        target = 0.0
+
+    if playing and stats.stalled():
+        # Frames were arriving and then stopped: say so loudly.
+        rows.append(("FPS", "STALLED", False))
+    else:
+        if measured > 0 and target > 0:
+            fps_text = "{0:.1f} / {1:g}".format(measured, target)
+        elif measured > 0:
+            fps_text = "{0:.1f}".format(measured)
+        else:
+            fps_text = "--"
+        rows.append(("FPS", fps_text, stats.is_realtime(target)))
+
+    if frame is not None:
+        total = "" if frame_count in (None, 0) else " / {0}".format(frame_count)
+        rows.append(("FRAME", "{0}{1}".format(frame, total), True))
+
+    if resolution:
+        text = "{0} x {1}".format(resolution[0], resolution[1])
+        if proxy_label:
+            text = "{0}   {1}".format(text, proxy_label)
+        rows.append(("RES", text, True))
+
+    decode = stats.average_decode_ms()
+    if decode > 0:
+        budget = (1000.0 / target) if target > 0 else 0
+        # A frame that takes longer to decode than its share of the clock cannot
+        # sustain real time, no matter how fast the rest of the pipeline is.
+        rows.append(
+            ("DECODE", "{0:.1f} ms".format(decode), not budget or decode <= budget)
+        )
+
+    if cached is not None:
+        rows.append(("CACHE", "{0} frames".format(cached), True))
+
+    if stats.dropped:
+        rows.append(("DROPPED", str(stats.dropped), False))
+
+    return rows
+
+
+def effective_target_fps(source_fps, playback_speed=1.0):
+    """Return the displayed FPS expected at the selected transport speed."""
+    try:
+        rate = float(source_fps)
+        multiplier = float(playback_speed)
+    except (TypeError, ValueError):
+        return 0.0
+    if rate <= 0 or multiplier <= 0 or rate != rate or multiplier != multiplier:
+        return 0.0
+    return rate * multiplier
+
+
+if __name__ == "__main__":
+    pass