From c0d1e1a3d5f1ab8802242619ecdd39f433945845 Mon Sep 17 00:00:00 2001 From: Eric Coissac Date: Tue, 31 Mar 2026 10:00:27 +0200 Subject: [PATCH] Add tracing logs and ReadList caching for OpenHome queue - Add detailed tracing logs in control_point, music_renderer, and openhome_renderer for queue length checks, auto_play flag consumption, playback state changes, and OpenHome transport state mapping. - Introduce a 500ms TTL cache for ReadList results in OpenHomeQueue to reduce redundant SOAP calls, especially during sync_queue operations. - Update all queue modification methods to invalidate the new read_list_cache. - Add debug logging for pivot search results in sync_queue. --- .DS_Store | Bin 18436 -> 18436 bytes pmocontrol/src/control_point.rs | 13 ++- .../src/music_renderer/musicrenderer.rs | 24 +++++ .../src/music_renderer/openhome_renderer.rs | 22 ++++- pmocontrol/src/queue/openhome.rs | 87 +++++++++++++++++- 5 files changed, 140 insertions(+), 6 deletions(-) diff --git a/.DS_Store b/.DS_Store index b37528614380d20bb943a33b4d980fdf4f02128b..eb344ba742cb9f4682b87c67b026cc93f58d7a32 100644 GIT binary patch delta 150 zcmZpfz}PZ@ae_Z%@5X@L{EX(4c?6 { + { + let s = self.state.lock().unwrap(); + tracing::trace!( + renderer = self.info.friendly_name(), + has_played = s.has_played_since_track_start, + playback_source = ?s.playback_source, + "STOPPED detected — evaluating auto-advance" + ); + } // Check if user requested stop (via Stop button in UI) if self.check_and_clear_user_stop_requested() { debug!( @@ -695,6 +710,15 @@ impl MusicRenderer { // Mark that we have seen a PLAYING state - auto-advance is now allowed self.set_has_played_flag(); } + PlaybackState::Transitioning => { + let s = self.state.lock().unwrap(); + tracing::trace!( + renderer = self.info.friendly_name(), + has_played = s.has_played_since_track_start, + playback_source = ?s.playback_source, + "TRANSITIONING detected" + ); + } _ => {} } } diff --git a/pmocontrol/src/music_renderer/openhome_renderer.rs b/pmocontrol/src/music_renderer/openhome_renderer.rs index 47002404..f046dcd4 100644 --- a/pmocontrol/src/music_renderer/openhome_renderer.rs +++ b/pmocontrol/src/music_renderer/openhome_renderer.rs @@ -342,8 +342,14 @@ impl VolumeControl for OpenHomeRenderer { impl PlaybackStatus for OpenHomeRenderer { fn playback_state(&self) -> Result { let client = self.playlist_client_for("playback_state")?; - let state = client.transport_state()?; - Ok(map_openhome_state(&state)) + let raw = client.transport_state()?; + let mapped = map_openhome_state(&raw); + tracing::trace!( + raw_state = raw.as_str(), + mapped_state = ?mapped, + "OpenHome TransportState" + ); + Ok(mapped) } } @@ -542,7 +548,19 @@ impl QueueTransportControl for OpenHomeRenderer { .queue .lock() .map_err(|_| ControlPointError::QueueError("Queue mutex poisoned".into()))?; + let len = queue.len().unwrap_or(0); + let current = queue.current_index().ok().flatten(); + tracing::trace!( + queue_len = len, + current_index = ?current, + "OpenHome play_next: advancing queue" + ); if !queue.advance()? { + tracing::trace!( + queue_len = len, + current_index = ?current, + "OpenHome play_next: advance() returned false — no next track" + ); return Err(ControlPointError::QueueError("No next track".into())); } } diff --git a/pmocontrol/src/queue/openhome.rs b/pmocontrol/src/queue/openhome.rs index c37b0be4..9b0d5eca 100644 --- a/pmocontrol/src/queue/openhome.rs +++ b/pmocontrol/src/queue/openhome.rs @@ -66,6 +66,50 @@ impl TrackIdsCache { } } +/// Cache for ReadList results to avoid redundant SOAP calls within a short window. +/// Key: sorted list of requested IDs. TTL: 500ms. +#[derive(Debug)] +struct ReadListCache { + ids: Option>, + entries: Option>, + last_update: Option, +} + +impl ReadListCache { + fn new() -> Self { + Self { + ids: None, + entries: None, + last_update: None, + } + } + + fn get(&self, id_list: &[u32]) -> Option> { + if let (Some(cached_ids), Some(entries), Some(last_update)) = + (&self.ids, &self.entries, self.last_update) + { + if let Ok(elapsed) = SystemTime::now().duration_since(last_update) { + if elapsed.as_millis() < 500 && cached_ids.as_slice() == id_list { + return Some(entries.clone()); + } + } + } + None + } + + fn set(&mut self, ids: Vec, entries: Vec) { + self.ids = Some(ids); + self.entries = Some(entries); + self.last_update = Some(SystemTime::now()); + } + + fn invalidate(&mut self) { + self.ids = None; + self.entries = None; + self.last_update = None; + } +} + /// Cache for current track ID to avoid redundant Id SOAP calls #[derive(Debug)] struct CurrentTrackIdCache { @@ -130,6 +174,8 @@ pub struct OpenHomeQueue { track_ids_cache: Arc>, /// Cache for current track ID to avoid redundant Id SOAP calls current_track_id_cache: Arc>, + /// Cache for ReadList results (TTL 500ms) to avoid redundant SOAP calls + read_list_cache: Arc>, } impl OpenHomeQueue { @@ -147,6 +193,7 @@ impl OpenHomeQueue { metadata_cache: Mutex::new(HashMap::new()), track_ids_cache: Arc::new(Mutex::new(TrackIdsCache::new())), current_track_id_cache: Arc::new(Mutex::new(CurrentTrackIdCache::new())), + read_list_cache: Arc::new(Mutex::new(ReadListCache::new())), } } @@ -406,6 +453,7 @@ impl OpenHomeQueue { // Invalidate cache after playlist modifications self.track_ids_cache.lock().unwrap().invalidate(); + self.read_list_cache.lock().unwrap().invalidate(); Ok(()) } @@ -584,6 +632,7 @@ impl OpenHomeQueue { // Invalidate cache after playlist modifications self.track_ids_cache.lock().unwrap().invalidate(); + self.read_list_cache.lock().unwrap().invalidate(); Ok(()) } @@ -686,6 +735,7 @@ impl OpenHomeQueue { // Invalidate cache after playlist modifications self.track_ids_cache.lock().unwrap().invalidate(); + self.read_list_cache.lock().unwrap().invalidate(); Ok(()) } @@ -890,13 +940,28 @@ impl QueueBackend for OpenHomeQueue { }); } - // Read metadata for all tracks (batched) - // playback_item_from_entry() will prioritize cached metadata over entry metadata + // Read metadata for all tracks (batched), with 500ms cache to avoid + // redundant SOAP calls during sync_queue (which calls queue_snapshot twice). const MAX_BATCH: usize = 64; let mut entries = Vec::with_capacity(ids.len()); for chunk in ids.chunks(MAX_BATCH) { + if let Some(cached) = self.read_list_cache.lock().unwrap().get(chunk) { + trace!( + renderer = self.renderer_id.0.as_str(), + "ReadList cache hit for {} IDs", + chunk.len() + ); + entries.extend(cached); + continue; + } match self.playlist_client.read_list(chunk) { - Ok(mut batch) => entries.append(&mut batch), + Ok(batch) => { + self.read_list_cache + .lock() + .unwrap() + .set(chunk.to_vec(), batch.clone()); + entries.extend(batch); + } Err(err) => { // If batch fails, try one by one if chunk.len() > 1 { @@ -947,6 +1012,7 @@ impl QueueBackend for OpenHomeQueue { } // Invalidate caches (seek_id/stop modifies playlist state and current track) self.track_ids_cache.lock().unwrap().invalidate(); + self.read_list_cache.lock().unwrap().invalidate(); self.current_track_id_cache.lock().unwrap().invalidate(); Ok(()) } @@ -972,6 +1038,7 @@ impl QueueBackend for OpenHomeQueue { // Invalidate caches after delete_all (clears queue and current track) self.track_ids_cache.lock().unwrap().invalidate(); + self.read_list_cache.lock().unwrap().invalidate(); self.current_track_id_cache.lock().unwrap().invalidate(); if items.is_empty() { @@ -994,6 +1061,7 @@ impl QueueBackend for OpenHomeQueue { // Invalidate cache after insertions self.track_ids_cache.lock().unwrap().invalidate(); + self.read_list_cache.lock().unwrap().invalidate(); Ok(()) } @@ -1005,6 +1073,7 @@ impl QueueBackend for OpenHomeQueue { self.metadata_cache.lock().unwrap().clear(); // Invalidate caches after delete_all (clears queue and current track) self.track_ids_cache.lock().unwrap().invalidate(); + self.read_list_cache.lock().unwrap().invalidate(); self.current_track_id_cache.lock().unwrap().invalidate(); return Ok(()); } @@ -1053,6 +1122,15 @@ impl QueueBackend for OpenHomeQueue { .position(|item| item.didl_id == playing_didl_id) }); + tracing::trace!( + renderer = self.renderer_id.0.as_str(), + playing_uri = playing_uri.as_str(), + playing_didl_id = ?playing_didl_id, + pivot_found = new_playing_idx.is_some(), + desired_uris = ?items.iter().map(|i| i.uri.as_str()).collect::>(), + "sync_queue: pivot search result" + ); + if let Some(pivot_idx) = new_playing_idx { // CASE 2: Currently playing item IS in the new playlist // Use gentle double-LCS strategy: preserve the pivot and sync before/after separately @@ -1142,6 +1220,7 @@ impl QueueBackend for OpenHomeQueue { // Invalidate cache after playlist modifications self.track_ids_cache.lock().unwrap().invalidate(); + self.read_list_cache.lock().unwrap().invalidate(); Ok(()) } @@ -1187,6 +1266,7 @@ impl QueueBackend for OpenHomeQueue { // Invalidate cache after playlist modifications (except ReplaceAll which already does it) self.track_ids_cache.lock().unwrap().invalidate(); + self.read_list_cache.lock().unwrap().invalidate(); Ok(()) } @@ -1199,6 +1279,7 @@ impl QueueBackend for OpenHomeQueue { self.playlist_client.delete_all()?; // Invalidate caches after clearing playlist (clears queue and current track) self.track_ids_cache.lock().unwrap().invalidate(); + self.read_list_cache.lock().unwrap().invalidate(); self.current_track_id_cache.lock().unwrap().invalidate(); Ok(()) }