diff --git a/alvr/server_core/src/lib.rs b/alvr/server_core/src/lib.rs index d78efe2833..b10c40a0ac 100644 --- a/alvr/server_core/src/lib.rs +++ b/alvr/server_core/src/lib.rs @@ -507,6 +507,38 @@ impl ServerCoreContext { .map(|stats| stats.duration_until_next_vsync()) } + pub fn last_game_time_latency(&self) -> Option { + self.connection_context + .statistics_manager + .read() + .as_ref() + .map(|stats| stats.last_game_time_latency()) + } + + pub fn last_compose_latency(&self) -> Option { + self.connection_context + .statistics_manager + .read() + .as_ref() + .map(|stats| stats.last_compose_latency()) + } + + pub fn last_frame_present_interval(&self) -> Option { + self.connection_context + .statistics_manager + .read() + .as_ref() + .map(|stats| stats.last_frame_present_interval()) + } + + pub fn display_interval(&self) -> Option { + self.connection_context + .statistics_manager + .read() + .as_ref() + .map(|stats| stats.display_interval()) + } + pub fn restart(self) { dbg_server_core!("restart"); diff --git a/alvr/server_core/src/statistics.rs b/alvr/server_core/src/statistics.rs index b67bfaf060..d2f4660b65 100644 --- a/alvr/server_core/src/statistics.rs +++ b/alvr/server_core/src/statistics.rs @@ -46,6 +46,8 @@ pub struct StatisticsManager { last_full_report_instant: Instant, last_frame_present_instant: Instant, last_frame_present_interval: Duration, + last_game_time_latency: Duration, + last_compose_latency: Duration, video_packets_total: usize, video_packets_partial_sum: usize, video_bytes_total: usize, @@ -73,6 +75,8 @@ impl StatisticsManager { last_full_report_instant: Instant::now(), last_frame_present_instant: Instant::now(), last_frame_present_interval: Duration::ZERO, + last_game_time_latency: Duration::ZERO, + last_compose_latency: Duration::ZERO, video_packets_total: 0, video_packets_partial_sum: 0, video_bytes_total: 0, @@ -94,11 +98,15 @@ impl StatisticsManager { } pub fn report_tracking_received(&mut self, target_timestamp: Duration) { - if !self + if let Some(frame) = self .history_buffer - .iter() - .any(|frame| frame.target_timestamp == target_timestamp) + .iter_mut() + .find(|frame| frame.target_timestamp == target_timestamp) { + // This shouldn't happen, but if an existing frame somehow gets new tracking, + // update the timestamp. + frame.tracking_received = Instant::now(); + } else { self.history_buffer.push_front(HistoryFrame { target_timestamp, tracking_received: Instant::now(), @@ -124,6 +132,10 @@ impl StatisticsManager { self.last_frame_present_instant = now; frame.frame_present = now; + + self.last_game_time_latency = frame + .frame_present + .saturating_duration_since(frame.tracking_received); } } @@ -134,6 +146,9 @@ impl StatisticsManager { .find(|frame| frame.target_timestamp == target_timestamp) { frame.frame_composed = Instant::now() - offset; + self.last_compose_latency = frame + .frame_composed + .saturating_duration_since(frame.frame_present); } } @@ -320,4 +335,20 @@ impl StatisticsManager { (self.last_vsync_time + self.frame_interval).saturating_duration_since(now) } + + pub fn last_game_time_latency(&self) -> Duration { + self.last_game_time_latency + } + + pub fn last_frame_present_interval(&self) -> Duration { + self.last_frame_present_interval + } + + pub fn display_interval(&self) -> Duration { + self.frame_interval + } + + pub fn last_compose_latency(&self) -> Duration { + self.last_compose_latency + } } diff --git a/alvr/server_openvr/src/lib.rs b/alvr/server_openvr/src/lib.rs index 4089d4ab63..40c64566cf 100644 --- a/alvr/server_openvr/src/lib.rs +++ b/alvr/server_openvr/src/lib.rs @@ -387,6 +387,7 @@ extern "C" fn wait_for_vsync() { // We use 120Hz-ish so that SteamVR doesn't accidentally get // any weird ideas about our display Hz with its frame pacing. static PRE_HEADSET_STATS_WAIT_INTERVAL: Duration = Duration::from_millis(8); + static DESYNC_THRESHOLD: Duration = Duration::from_millis(2); // NB: don't sleep while locking SERVER_DATA_MANAGER or SERVER_CORE_CONTEXT let sleep_duration = SERVER_CORE_CONTEXT @@ -394,14 +395,56 @@ extern "C" fn wait_for_vsync() { .as_ref() .and_then(|ctx| ctx.duration_until_next_vsync()); + let display_interval = SERVER_CORE_CONTEXT + .read() + .as_ref() + .and_then(|ctx| ctx.display_interval()) + .unwrap_or(PRE_HEADSET_STATS_WAIT_INTERVAL); + + let last_game_time_latency = SERVER_CORE_CONTEXT + .read() + .as_ref() + .and_then(|ctx| ctx.last_game_time_latency()) + .unwrap_or(Duration::from_millis(0)); + + let last_compositing_latency = SERVER_CORE_CONTEXT + .read() + .as_ref() + .and_then(|ctx| ctx.last_compose_latency()) + .unwrap_or(Duration::from_millis(0)); + + let last_frame_present_interval = SERVER_CORE_CONTEXT + .read() + .as_ref() + .and_then(|ctx| ctx.last_frame_present_interval()) + .unwrap_or(display_interval); + if let Some(duration) = sleep_duration { if alvr_server_core::settings() .video .enforce_server_frame_pacing { - thread::sleep(duration); + // Nominally the compositing latency is extremely small, however it + // can shoot up if the GPU is fully scheduled. Only the game render time + // should influence the presentation frame-to-frame latency. + thread::sleep(duration.saturating_sub(last_compositing_latency)); } else { - thread::yield_now(); + // This is a bit convoluted but basically the game time latency isn't real, + // it's based on motion-to-photon, so Unity games that use old poses will have extra latency. + // + // So, the actual conditions for not sleeping at all are: + // - The game time has to be nearing the display interval + // - The compositing latency has to be high, indicating that the GPU is fully scheduled + // because the game is actually taking 10+ms to render + // - As an extra fallback, the roundtrip present interval (server FPS) should not be lower than the display interval + if last_game_time_latency <= (display_interval - DESYNC_THRESHOLD) + || (last_compositing_latency <= DESYNC_THRESHOLD) + || (last_frame_present_interval < display_interval) + { + thread::sleep(duration.saturating_sub(last_compositing_latency)); + } else { + thread::yield_now(); + } } } else { // StatsManager isn't up because the headset hasn't connected,