debug(suggestions): add detailed timing logs for debugging

Frontend logging:
- Log when effect triggers with artist count
- Log when backend call starts/finishes with timing
- Log result details (tracks, artists counts)

Backend logging (playlist_suggestions.rs):
- Log MBID resolution with cache hits/misses/failures
- Log config values
- Log engine call timing

Engine logging (suggestions.rs):
- Step 1: ensure_vector timing per artist
- Step 2: playlist vector computation
- Step 3: find_nearest timing
- Step 4: track search timing per artist
- Early exit when pool size reached

src-tauri/src/artist_vectors/suggestions.rs

@@ -123,7 +123,10 @@ impl SuggestionsEngine {
         exclude_track_ids: &HashSet<u64>,
         include_reasons: bool,
     ) -> Result<SuggestionResult, String> {
+        use std::time::Instant;
+
         if playlist_artist_mbids.is_empty() {
+            log::debug!("[SuggestionsEngine] Empty playlist, returning empty");
             return Ok(SuggestionResult {
                 tracks: Vec::new(),
                 source_artists: Vec::new(),
@@ -133,17 +136,26 @@ impl SuggestionsEngine {
         }
 
         // 1. Ensure vectors exist for playlist artists
-        for mbid in playlist_artist_mbids {
+        log::info!("[SuggestionsEngine] Step 1: Ensuring vectors for {} artists", playlist_artist_mbids.len());
+        let step1_start = Instant::now();
+        for (i, mbid) in playlist_artist_mbids.iter().enumerate() {
+            let artist_start = Instant::now();
             let _ = self
                 .builder
                 .ensure_vector(mbid, None, None, self.config.vector_max_age_days)
                 .await;
+            log::debug!("[SuggestionsEngine] ensure_vector {}/{} took {:?}", i + 1, playlist_artist_mbids.len(), artist_start.elapsed());
         }
+        log::info!("[SuggestionsEngine] Step 1 completed in {:?}", step1_start.elapsed());
 
         // 2. Compute combined playlist vector
+        log::info!("[SuggestionsEngine] Step 2: Computing playlist vector");
+        let step2_start = Instant::now();
         let playlist_vector = self.compute_playlist_vector(playlist_artist_mbids).await?;
+        log::info!("[SuggestionsEngine] Step 2 completed in {:?}, vector empty={}", step2_start.elapsed(), playlist_vector.is_empty());
 
         if playlist_vector.is_empty() {
+            log::warn!("[SuggestionsEngine] Playlist vector is empty, returning empty result");
             return Ok(SuggestionResult {
                 tracks: Vec::new(),
                 source_artists: Vec::new(),
@@ -153,18 +165,23 @@ impl SuggestionsEngine {
         }
 
         // 3. Find nearest artists (excluding playlist artists)
+        log::info!("[SuggestionsEngine] Step 3: Finding nearest artists");
+        let step3_start = Instant::now();
         let exclude_vec: Vec<String> = playlist_artist_mbids.to_vec();
         let similar_artists = {
             let store = self.store.lock().await;
             store.find_nearest(&playlist_vector, self.config.max_artists, &exclude_vec)?
         };
+        log::info!("[SuggestionsEngine] Step 3 completed in {:?}, found {} similar artists", step3_start.elapsed(), similar_artists.len());
 
         let similar_artists_count = similar_artists.len();
         let mut source_artists = Vec::new();
         let mut all_tracks = Vec::new();
 
         // 4. Search for tracks by similar artists
-        for artist in &similar_artists {
+        log::info!("[SuggestionsEngine] Step 4: Searching tracks for similar artists");
+        let step4_start = Instant::now();
+        for (i, artist) in similar_artists.iter().enumerate() {
             if artist.similarity < self.config.min_similarity {
                 continue;
             }
@@ -172,9 +189,12 @@ impl SuggestionsEngine {
             source_artists.push(artist.name.clone().unwrap_or_else(|| artist.mbid.clone()));
 
             // Search Qobuz for tracks by this artist
+            let search_start = Instant::now();
             let tracks = self
                 .search_artist_tracks(&artist.mbid, artist.name.as_deref(), artist.similarity)
                 .await;
+            log::debug!("[SuggestionsEngine] search_artist_tracks {}/{} took {:?}, got {} tracks",
+                i + 1, similar_artists.len(), search_start.elapsed(), tracks.len());
 
             for mut track in tracks {
                 // Skip if already in playlist
@@ -197,9 +217,11 @@ impl SuggestionsEngine {
 
             // Stop if we have enough tracks
             if all_tracks.len() >= self.config.max_pool_size {
+                log::info!("[SuggestionsEngine] Reached pool size {} after {} artists", all_tracks.len(), i + 1);
                 break;
             }
         }
+        log::info!("[SuggestionsEngine] Step 4 completed in {:?}, got {} tracks", step4_start.elapsed(), all_tracks.len());
 
         // 5. Sort by similarity score and limit pool size
         all_tracks.sort_by(|a, b| {

src-tauri/src/commands/playlist_suggestions.rs

@@ -45,8 +45,21 @@ pub async fn get_playlist_suggestions_v2(
     mb_state: State<'_, MusicBrainzSharedState>,
     app_state: State<'_, AppState>,
 ) -> Result<SuggestionResult, String> {
+    use std::time::Instant;
+    let total_start = Instant::now();
+
+    log::info!(
+        "[Suggestions] Starting for {} artists, exclude {} tracks",
+        input.artists.len(),
+        input.exclude_track_ids.len()
+    );
+
     // Resolve artist names to MBIDs (with caching)
+    let resolve_start = Instant::now();
     let mut artist_mbids = Vec::new();
+    let mut cached_count = 0;
+    let mut resolved_count = 0;
+    let mut failed_count = 0;
 
     for artist in &input.artists {
         // Check cache first
@@ -61,9 +74,13 @@ pub async fn get_playlist_suggestions_v2(
                     && resolved.confidence != MatchConfidence::Low
                 {
                     artist_mbids.push(mbid);
+                    cached_count += 1;
                     continue;
                 }
             }
+            // Cached as "no match"
+            failed_count += 1;
+            continue;
         }
 
         // Try to resolve via MusicBrainz search
@@ -91,13 +108,16 @@ pub async fn get_playlist_suggestions_v2(
                             let _ = cache.set_artist(&artist.name, &resolved);
                         }
                         artist_mbids.push(mbid);
+                        resolved_count += 1;
                         continue;
                     }
                 }
                 Err(e) => {
-                    log::debug!("Failed to resolve artist '{}': {}", artist.name, e);
+                    log::warn!("[Suggestions] MusicBrainz search failed for '{}': {}", artist.name, e);
                 }
             }
+        } else {
+            log::debug!("[Suggestions] MusicBrainz disabled, skipping '{}'", artist.name);
         }
 
         // Cache negative result
@@ -105,15 +125,20 @@ pub async fn get_playlist_suggestions_v2(
             let cache = mb_state.cache.lock().await;
             let _ = cache.set_artist(&artist.name, &ResolvedArtist::empty());
         }
+        failed_count += 1;
     }
 
+    let resolve_elapsed = resolve_start.elapsed();
     log::info!(
-        "Resolved {}/{} artists to MBIDs for suggestions",
-        artist_mbids.len(),
-        input.artists.len()
+        "[Suggestions] MBID resolution took {:?}: {} cached, {} resolved, {} failed",
+        resolve_elapsed,
+        cached_count,
+        resolved_count,
+        failed_count
     );
 
     if artist_mbids.is_empty() {
+        log::warn!("[Suggestions] No MBIDs resolved, returning empty result");
         return Ok(SuggestionResult {
             tracks: Vec::new(),
             source_artists: Vec::new(),
@@ -133,6 +158,9 @@ pub async fn get_playlist_suggestions_v2(
 
     // Create the engine with config
     let config = input.config.unwrap_or_default();
+    log::info!("[Suggestions] Config: max_artists={}, tracks_per={}, pool_size={}",
+        config.max_artists, config.tracks_per_artist, config.max_pool_size);
+
     let engine = SuggestionsEngine::new(
         store_state.store.clone(),
         builder,
@@ -144,9 +172,32 @@ pub async fn get_playlist_suggestions_v2(
     let exclude_set: HashSet<u64> = input.exclude_track_ids.into_iter().collect();
 
     // Generate suggestions
-    engine
+    log::info!("[Suggestions] Calling engine.generate_suggestions with {} MBIDs", artist_mbids.len());
+    let engine_start = std::time::Instant::now();
+
+    let result = engine
         .generate_suggestions(&artist_mbids, &exclude_set, input.include_reasons)
-        .await
+        .await;
+
+    let engine_elapsed = engine_start.elapsed();
+    let total_elapsed = total_start.elapsed();
+
+    match &result {
+        Ok(r) => {
+            log::info!(
+                "[Suggestions] Engine took {:?}, total {:?}. Result: {} tracks from {} similar artists",
+                engine_elapsed,
+                total_elapsed,
+                r.tracks.len(),
+                r.similar_artists_count
+            );
+        }
+        Err(e) => {
+            log::error!("[Suggestions] Engine failed after {:?}: {}", engine_elapsed, e);
+        }
+    }
+
+    result
 }
 
 /// Get store statistics for debugging