diff --git a/app/jittermonitor.py b/app/jittermonitor.py index 4b1bf6c..147ec4e 100644 --- a/app/jittermonitor.py +++ b/app/jittermonitor.py @@ -1,27 +1,56 @@ -from PyQt6.QtCore import QObject, QTimer, QElapsedTimer, pyqtSignal +from PyQt6.QtCore import QObject, QTimer, QElapsedTimer +import logging +import time + +from config import Config class EventLoopJitterMonitor(QObject): - long_pause_detected = pyqtSignal(float) # pause length in ms - - def __init__(self, parent=None, interval_ms: int = 20, threshold_ms: int = 80): + def __init__( + self, + parent=None, + interval_ms: int = 20, + jitter_threshold_ms: int = 100, + log_cooldown_s: float = 1.0, + ): super().__init__(parent) self._interval = interval_ms - self._threshold = threshold_ms + self._jitter_threshold = jitter_threshold_ms + self._log_cooldown_s = log_cooldown_s + self._timer = QTimer(self) self._timer.setInterval(self._interval) self._timer.timeout.connect(self._on_timeout) + self._elapsed = QElapsedTimer() self._elapsed.start() self._last = self._elapsed.elapsed() + # child logger: e.g. "musicmuster.jitter" + self._log = logging.getLogger(f"{Config.LOG_NAME}.jitter") + self._last_log_time = 0.0 + def start(self) -> None: self._timer.start() def _on_timeout(self) -> None: - now = self._elapsed.elapsed() - delta = now - self._last # ms since last timeout - self._last = now - if delta > self._interval + self._threshold: - # log somewhere with timestamp + current track + position - print(f"[JITTER] {delta} ms gap in event loop") - self.long_pause_detected.emit(delta) + now_ms = self._elapsed.elapsed() + delta = now_ms - self._last + self._last = now_ms + + if delta > (self._interval + self._jitter_threshold): + self._log_jitter(now_ms, delta) + + def _log_jitter(self, now_ms: int, gap_ms: int) -> None: + now = time.monotonic() + + # simple rate limit: only one log every log_cooldown_s + if now - self._last_log_time < self._log_cooldown_s: + return + self._last_log_time = now + + self._log.warning( + "Event loop gap detected: t=%d ms, gap=%d ms (interval=%d ms)", + now_ms, + gap_ms, + self._interval, + ) diff --git a/app/logging.yaml b/app/logging.yaml index fa07d8e..afdc668 100644 --- a/app/logging.yaml +++ b/app/logging.yaml @@ -23,8 +23,8 @@ filters: # - function-name-1 # - function-name-2 musicmuster: - - update_clocks - play_next + jittermonitor: [] handlers: stderr: diff --git a/app/music_manager.py b/app/music_manager.py index 7d14f64..60b44ce 100644 --- a/app/music_manager.py +++ b/app/music_manager.py @@ -3,6 +3,7 @@ from __future__ import annotations import datetime as dt from time import sleep +import time from typing import Optional # Third party imports @@ -30,6 +31,7 @@ from log import log from models import PlaylistRows from vlcmanager import VLCManager + # Define the VLC callback function type # import ctypes # import platform @@ -353,21 +355,6 @@ class _Music: self.player.set_position(position) self.start_dt = start_time - # For as-yet unknown reasons. sometimes the volume gets - # reset to zero within 200mS or so of starting play. This - # only happened since moving to Debian 12, which uses - # Pipewire for sound (which may be irrelevant). - # It has been known for the volume to need correcting more - # than once in the first 200mS. - # Update August 2024: This no longer seems to be an issue - # for _ in range(3): - # if self.player: - # volume = self.player.audio_get_volume() - # if volume < Config.VLC_VOLUME_DEFAULT: - # self.set_volume(Config.VLC_VOLUME_DEFAULT) - # log.error(f"Reset from {volume=}") - # sleep(0.1) - def set_position(self, position: float) -> None: """ Set player position @@ -391,17 +378,6 @@ class _Music: volume = Config.VLC_VOLUME_DEFAULT self.player.audio_set_volume(volume) - # Ensure volume correct - # For as-yet unknown reasons. sometimes the volume gets - # reset to zero within 200mS or so of starting play. This - # only happened since moving to Debian 12, which uses - # Pipewire for sound (which may be irrelevant). - for _ in range(3): - current_volume = self.player.audio_get_volume() - if current_volume < volume: - self.player.audio_set_volume(volume) - log.debug(f"Reset from {volume=}") - sleep(0.1) def stop(self) -> None: """Immediately stop playing""" diff --git a/app/musicmuster.py b/app/musicmuster.py index da3c025..6347aab 100755 --- a/app/musicmuster.py +++ b/app/musicmuster.py @@ -1207,7 +1207,14 @@ class Window(QMainWindow): self.action_quicklog = QShortcut(QKeySequence("Ctrl+L"), self) self.action_quicklog.activated.connect(self.quicklog) - self.jitter_monitor = EventLoopJitterMonitor(self) + + # Jitter monitor - log delays in main event loop + self.jitter_monitor = EventLoopJitterMonitor( + parent=self, + interval_ms=20, + jitter_threshold_ms=100, # only care about >~100 ms + log_cooldown_s=1.0, # at most 1 warning per second + ) self.jitter_monitor.start() self.load_last_playlists() @@ -2210,14 +2217,6 @@ class Window(QMainWindow): if self.return_pressed_in_error(): return - # Issue #223 concerns a very short pause (maybe 0.1s) sometimes - # when starting to play at track. Resolution appears to be to - # disable timer10 for a short time. Timer is re-enabled in - # update_clocks. - - self.timer10.stop() - log.debug("issue223: play_next: 10ms timer disabled") - # If there's currently a track playing, fade it. if track_sequence.current: track_sequence.current.fade() @@ -2729,8 +2728,7 @@ class Window(QMainWindow): # WARNING_MS_BEFORE_FADE milliseconds before fade starts, set # warning colour on time to silence box and enable play - # controls. This is also a good time to re-enable the 10ms - # timer (see play_next() and issue #223). + # controls. elif time_to_fade <= Config.WARNING_MS_BEFORE_FADE: self.footer_section.frame_fade.setStyleSheet( @@ -2738,11 +2736,6 @@ class Window(QMainWindow): ) self.catch_return_key = False self.show_status_message("Play controls: Enabled", 0) - # Re-enable 10ms timer (see above) - log.debug(f"issue287: {self.timer10.isActive()=}") - if not self.timer10.isActive(): - self.timer10.start(10) - log.debug("issue223: update_clocks: 10ms timer enabled") else: self.footer_section.frame_silent.setStyleSheet("") diff --git a/app/playlistmodel.py b/app/playlistmodel.py index 0b3029a..027397e 100644 --- a/app/playlistmodel.py +++ b/app/playlistmodel.py @@ -765,8 +765,6 @@ class PlaylistModel(QAbstractTableModel): Signal to view to refresh invalidated row """ - log.debug(f"issue285: {self}: invalidate_row({modified_row=})") - self.dataChanged.emit( self.index(modified_row, 0), self.index(modified_row, self.columnCount() - 1), @@ -778,8 +776,6 @@ class PlaylistModel(QAbstractTableModel): Signal to view to refresh invlidated rows """ - log.debug(f"issue285: {self}: invalidate_rows({modified_rows=})") - for modified_row in modified_rows: # only invalidate required roles self.invalidate_row(modified_row, roles) @@ -1201,8 +1197,6 @@ class PlaylistModel(QAbstractTableModel): looking up the playlistrow_id and retrieving the row number from the database. """ - log.debug(f"issue285: {self}: reset_track_sequence_row_numbers()") - # Check the track_sequence.next, current and previous plrs and # update the row number with db.Session() as session: @@ -1667,8 +1661,6 @@ class PlaylistModel(QAbstractTableModel): Update track start/end times in self.playlist_rows """ - log.debug(f"issue285: {self}: update_track_times()") - next_start_time: Optional[dt.datetime] = None update_rows: list[int] = [] row_count = len(self.playlist_rows)