pmomusic/Blackboard/Report/fix-openhome-polling-regression.md

Rapport : Correction de la régression du polling OpenHome

Résumé

Suite au crash de Claude Code, investigation et correction d'une régression causant des sauts de 2-3 secondes dans la barre de progression de l'interface web pour les renderers OpenHome. Le problème provenait d'une combinaison de facteurs : timing incorrect de la boucle de polling et appels SOAP redondants.

Fichiers modifiés

1. pmocontrol/src/music_renderer/musicrenderer.rs

   • Correction du timing de la boucle watcher (intervalle fixe au lieu de pause fixe)
   • Suppression d'un appel double à playback_position()
   • Réorganisation de poll_and_emit_changes() pour minimiser le temps passé avec les locks

2. pmocontrol/src/music_renderer/openhome_renderer.rs

   • Ajout d'un cache intelligent pour playback_position() avec timestamp et détection d'abus
   • Évite les appels SOAP redondants (OpenHome a précision à la seconde)

3. pmocontrol/src/music_renderer/watcher.rs

   • Modifications temporaires annulées (cache déplacé dans OpenHomeRenderer)

Analyse des appels SOAP OpenHome - Services de LECTURE

Analyse effectuée sur le renderer OpenHome pizzicato-Music (192.168.0.200) à partir des logs pmomusic.log.

Services analysés et intervalles observés

✅ Time:Time (après correction)

• Intervalle moyen : ~1050ms
• Min/Max : 1000-1200ms
• État : CORRIGÉ - Cache actif, fonctionne parfaitement
• Appels : Réguliers, espacés d'environ 1 seconde

⚠️ Playlist:TransportState

• Intervalle moyen : ~150ms
• Distribution :
  • 100ms : 7 occurrences
  • 200ms : 1 occurrence
  • 700ms : 1 occurrence
• État : PROBLÉMATIQUE - Sur-sollicitation
• Impact : Appelé 6-7 fois par seconde au lieu de 2 fois

⚠️ Playlist:IdArray

• Intervalle moyen : ~320ms (très irrégulier)
• Distribution :
  • 0ms : 2 occurrences (!)
  • 100ms : 3 occurrences
  • 200ms : 1 occurrence
  • 800-1000ms : 3 occurrences
• État : TRÈS PROBLÉMATIQUE - Appels anarchiques
• Impact : Certains appels consécutifs sans délai, surcharge réseau

⚠️ Product:SourceXml

• Intervalle moyen : ~130ms
• Distribution :
  • 100ms : 8 occurrences
  • 200ms : 1 occurrence
  • 300ms : 1 occurrence
• État : PROBLÉMATIQUE - Sur-sollicitation
• Impact : Appelé 7-8 fois par seconde au lieu de 2 fois

⚠️ Product:SourceIndex

• Données : Observé dans les logs mais pas analysé en détail
• État : Probablement similaire à SourceXml

📊 Volume:Volume & Volume:Mute

• Données : Insuffisantes dans les logs récents
• Polling prévu : Toutes les 2 ticks (1 seconde) selon le code
• État : À surveiller

Services d'ÉCRITURE

Aucun appel récent observé dans les logs (comportement normal - ce sont des commandes utilisateur ponctuelles) :

• Playlist:Play
• Playlist:Pause
• Playlist:Stop
• Playlist:SeekId
• Playlist:SeekSecondAbsolute
• Volume:SetVolume
• Volume:SetMute

Problèmes identifiés

1. Timing de la boucle watcher (CORRIGÉ)

Avant : sleep(500ms) APRÈS chaque poll

• Poll prend 100-200ms → Intervalle réel = 600-700ms

Après : Intervalle fixe de 500ms entre le DÉBUT de chaque poll

• Utilise SystemTime pour calculer le prochain poll
• Ajuste le sleep en conséquence

2. Lock contention (CORRIGÉ)

Avant : Lock watched_state tenu pendant les appels réseau

• Bloque autres threads pendant 50-200ms
• Cause des délais cumulatifs

Après : Locks acquis uniquement pour comparaison/mise à jour

• Appels réseau faits SANS locks
• Locks relâchés avant émission d'événements

3. Appels SOAP redondants OpenHome:Time (CORRIGÉ)

Avant : Aucun cache, appel SOAP à chaque poll (500ms)

• OpenHome retourne elapsed_secs (précision seconde)
• Appels inutiles car valeur identique

Après : Cache avec expiration 900ms + détection d'abus

• Retourne valeur cachée si < 900ms
• Warning si > 3 appels/seconde
• Réduit appels SOAP de moitié

4. Appel double à playback_position() (CORRIGÉ)

Avant : Deux appels dans poll_and_emit_changes()

let raw_position = self.lock_backend_for("poll_position").playback_position().ok();
let position = self.playback_position().ok();

Après : Un seul appel

let position = self.playback_position().ok();

Problèmes restants (NON CORRIGÉS)

Services OpenHome sur-sollicités

Les services suivants sont appelés trop fréquemment (100-300ms au lieu de 500ms+) :

• Playlist:TransportState (~150ms) - utilisé par playback_state()
• Playlist:IdArray (~320ms, irrégulier) - utilisé par les opérations de queue
• Product:SourceXml (~130ms) - vérification de source active
• Product:SourceIndex (non mesuré) - probablement similaire

Impact :

• Surcharge réseau inutile
• Potentiel de ralentissement avec latence réseau élevée
• Gaspillage CPU (parsing SOAP)

Solution recommandée : Appliquer le même pattern de cache qu'on a fait pour Time:Time à ces méthodes :

• playback_state() → cache TransportState
• Méthodes de queue → cache IdArray
• Vérification de source → cache SourceXml/SourceIndex

Tests et validation

• Compilation : ✅ Succès (15:38 heure de Paris)
• Logs analysés : pmomusic.log (14:54 UTC = 15:54 Paris)
• Barre de progression : ✅ Fluide (confirmé par utilisateur)
• Appels Time : ✅ Espacés de ~1s (au lieu de 0.6-1.8s avant)
• Warnings abus : ✅ Aucun (< 3 appels/seconde)

Conclusion

La régression de la barre de progression est corrigée. Le service Time bénéficie maintenant d'un cache intelligent qui évite les appels redondants. Cependant, l'analyse des logs révèle que d'autres services OpenHome souffrent du même problème de sur-sollicitation et mériteraient le même traitement.

Métriques

• Temps d'investigation : ~2h (après crash)
• Crates modifiés : pmocontrol
• Lignes modifiées : ~150 (ajouts + suppressions)
• Services corrigés : 1/5 identifiés