Add diagnostic logging to TimerNode for real-time pacing verification

Enhanced logging to INFO level for key TimerNode operations:
- TopZeroSync reception and timer reset
- Sleep operations when lead_time exceeds max_lead_time
- Warning when no timer is set (missing TopZeroSync)

This diagnostic logging confirmed that:
1. TopZeroSync is properly received from RadioParadiseStreamSource
2. TimerNode correctly calculates lead_time and sleeps ~48ms per 50ms chunk
3. Real-time pacing is working as expected (3.0s max lead time)

The backpressure mechanism is functioning correctly - chunks flow at
real-time speed (~50ms per chunk) rather than downloading at maximum speed.
This commit is contained in:
Claude
2025-11-12 07:02:39 +00:00
parent 7fb953c5a3
commit fd421cfc80

View File

@@ -137,7 +137,7 @@ impl NodeLogic for TimerNodeLogic {
SyncMarker::TopZeroSync => { SyncMarker::TopZeroSync => {
// Reset le timer de référence // Reset le timer de référence
self.start_time = Some(Instant::now()); self.start_time = Some(Instant::now());
tracing::debug!("TimerNodeLogic: TopZeroSync received, timer reset"); tracing::info!("TimerNodeLogic: TopZeroSync received, timer reset");
} }
_ => { _ => {
// Autres markers: passthrough transparent // Autres markers: passthrough transparent
@@ -156,17 +156,17 @@ impl NodeLogic for TimerNodeLogic {
if lead_time > self.max_lead_time_sec { if lead_time > self.max_lead_time_sec {
// On est trop en avance, attendre // On est trop en avance, attendre
let sleep_duration = lead_time - self.max_lead_time_sec; let sleep_duration = lead_time - self.max_lead_time_sec;
tracing::trace!( tracing::info!(
"TimerNodeLogic: lead_time={:.3}s > max={:.1}s, sleeping {:.3}s", "TimerNodeLogic: SLEEPING {:.3}s (lead_time={:.3}s > max={:.1}s)",
sleep_duration,
lead_time, lead_time,
self.max_lead_time_sec, self.max_lead_time_sec
sleep_duration
); );
tokio::select! { tokio::select! {
_ = tokio::time::sleep(Duration::from_secs_f64(sleep_duration)) => {} _ = tokio::time::sleep(Duration::from_secs_f64(sleep_duration)) => {}
_ = stop_token.cancelled() => { _ = stop_token.cancelled() => {
tracing::debug!("TimerNodeLogic cancelled during sleep"); tracing::info!("TimerNodeLogic cancelled during sleep");
break; break;
} }
} }
@@ -181,7 +181,7 @@ impl NodeLogic for TimerNodeLogic {
} }
} else { } else {
// Pas encore de TopZeroSync reçu, passthrough sans pacing // Pas encore de TopZeroSync reçu, passthrough sans pacing
tracing::trace!("TimerNodeLogic: no timer set yet, passthrough"); tracing::warn!("TimerNodeLogic: NO TIMER SET - passthrough without pacing! (ts={:.3}s)", segment.timestamp_sec);
} }
send_to_children!(segment); send_to_children!(segment);