[client/idd] harden demand-driven frame delivery

client/src/frame_scheduler.c

@@ -217,7 +217,16 @@ void frameScheduler_update(void)
         now - l_frameScheduler.lastCadence > FRAME_SCHEDULER_RENEW_NS * 2)
     {
       if (sendSchedule(LG_TRANSPORT_FRAME_SCHEDULE_RELEASE, 0))
+      {
         l_frameScheduler.active = false;
+        l_frameScheduler.period = 0;
+        LG_LOCK(l_frameScheduler.lock);
+        l_frameScheduler.phaseError          = 0;
+        l_frameScheduler.feedbackFrameSerial = 0;
+        l_frameScheduler.feedbackSamples     = 0;
+        l_frameScheduler.feedbackDirty       = false;
+        LG_UNLOCK(l_frameScheduler.lock);
+      }
     }
     return;
   }
@@ -235,6 +244,12 @@ void frameScheduler_update(void)
   {
     l_frameScheduler.period = period;
     ++l_frameScheduler.generation;
+    LG_LOCK(l_frameScheduler.lock);
+    l_frameScheduler.phaseError          = 0;
+    l_frameScheduler.feedbackFrameSerial = 0;
+    l_frameScheduler.feedbackSamples     = 0;
+    l_frameScheduler.feedbackDirty       = false;
+    LG_UNLOCK(l_frameScheduler.lock);
   }
   else
     l_frameScheduler.period =
@@ -282,12 +297,11 @@ void frameScheduler_observeRender(uint64_t timestamp)
 }
 
 void frameScheduler_feedback(uint64_t frameSerial, uint32_t generation,
-    uint64_t queueStart, uint64_t prepareStart)
+    uint64_t measuredPhase)
 {
-  if (!generation || !queueStart || prepareStart < queueStart)
+  if (!generation)
     return;
 
-  const uint64_t slack = prepareStart - queueStart;
   LG_LOCK(l_frameScheduler.lock);
   if (!l_frameScheduler.supported || !l_frameScheduler.active ||
       generation != l_frameScheduler.generation)
@@ -296,14 +310,21 @@ void frameScheduler_feedback(uint64_t frameSerial, uint32_t generation,
     return;
   }
 
-  int64_t error = slack > FRAME_SCHEDULER_TARGET_SLACK_NS ?
-    (int64_t)(slack - FRAME_SCHEDULER_TARGET_SLACK_NS) :
-    -(int64_t)(FRAME_SCHEDULER_TARGET_SLACK_NS - slack);
-  const int64_t limit = (int64_t)(l_frameScheduler.period / 2);
-  if (error > limit)
-    error = limit;
-  else if (error < -limit)
-    error = -limit;
+  const int64_t period = (int64_t)l_frameScheduler.period;
+  if (!period)
+  {
+    LG_UNLOCK(l_frameScheduler.lock);
+    return;
+  }
+
+  int64_t error = measuredPhase > FRAME_SCHEDULER_TARGET_SLACK_NS ?
+    (int64_t)(measuredPhase - FRAME_SCHEDULER_TARGET_SLACK_NS) :
+    -(int64_t)(FRAME_SCHEDULER_TARGET_SLACK_NS - measuredPhase);
+  error %= period;
+  if (error > period / 2)
+    error -= period;
+  else if (error < -period / 2)
+    error += period;
 
   if (!l_frameScheduler.feedbackSamples)
     l_frameScheduler.phaseError = error;

client/src/frame_scheduler.h

@@ -32,6 +32,6 @@ void frameScheduler_stop(void);
 void frameScheduler_update(void);
 void frameScheduler_observeRender(uint64_t timestamp);
 void frameScheduler_feedback(uint64_t frameSerial, uint32_t generation,
-    uint64_t queueStart, uint64_t prepareStart);
+    uint64_t measuredPhase);
 
 #endif

client/src/main.c

@@ -434,8 +434,18 @@ static void frameTimingFinishRender(const LG_RendererFrameTiming * timing,
   }
   LG_UNLOCK(l_frameTiming.lock);
 
-  frameScheduler_feedback(feedbackFrameSerial, feedbackGeneration,
-      feedbackQueueStart, prepareStart);
+  if (feedbackFrameSerial && feedbackGeneration)
+  {
+    uint64_t measuredPhase = timing->swapTime;
+    if (g_state.jitRender)
+    {
+      if (!feedbackQueueStart || prepareStart < feedbackQueueStart)
+        return;
+      measuredPhase = prepareStart - feedbackQueueStart;
+    }
+    frameScheduler_feedback(
+        feedbackFrameSerial, feedbackGeneration, measuredPhase);
+  }
 }
 
 static void frameTimingPublishReady(void)

idd/LGIdd/CFrameScheduler.cpp

@@ -22,13 +22,12 @@
 
 #include "CDebug.h"
 
-#include <algorithm>
-
 static const uint64_t MIN_PERIOD_NS   = 2000000ULL;
 static const uint64_t MAX_PERIOD_NS   = 1000000000ULL;
 static const uint32_t MIN_LEASE_MS    = 100;
 static const uint32_t MAX_LEASE_MS    = 5000;
 static const uint64_t MIN_SAFETY_NS   = 250000ULL;
+static const uint64_t LOG_INTERVAL_NS = 5000000000ULL;
 
 uint64_t CFrameScheduler::Nanotime()
 {
@@ -112,6 +111,11 @@ void CFrameScheduler::ElectOwner(uint64_t now)
     m_forceNext    = m_scheduling;
 
     m_lastPublishedFrameSerial = 0;
+    m_lastPhaseError            = 0;
+    m_lastLog                   = now;
+    m_lastLogAcquired           = m_acquiredFrames;
+    m_lastLogSkipped            = m_skippedFrames;
+    m_lastLogPublished          = m_publishedFrames;
 
     if (m_scheduling)
       DEBUG_INFO("Frame timing owner %u generation %u at %.3f Hz",
@@ -140,6 +144,15 @@ void CFrameScheduler::Reset()
   m_timingSamples  = 0;
 
   m_lastPublishedFrameSerial = 0;
+
+  m_lastPhaseError   = 0;
+  m_acquiredFrames   = 0;
+  m_skippedFrames    = 0;
+  m_publishedFrames  = 0;
+  m_lastLog          = 0;
+  m_lastLogAcquired  = 0;
+  m_lastLogSkipped   = 0;
+  m_lastLogPublished = 0;
   ReleaseSRWLockExclusive(&m_lock);
 }
 
@@ -260,9 +273,20 @@ void CFrameScheduler::ApplyFeedback(Client& client,
     m_nextDeadline = m_nextDeadline > advance ?
       m_nextDeadline - advance : 0;
   }
+  m_lastPhaseError = schedule.phaseError;
   client.lastFeedbackFrameSerial = schedule.feedbackFrameSerial;
 }
 
+void CFrameScheduler::AdvanceDeadline(uint64_t now)
+{
+  if (m_nextDeadline > now)
+    return;
+
+  const uint64_t periods =
+    (now - m_nextDeadline) / m_schedule.period + 1;
+  m_nextDeadline += periods * m_schedule.period;
+}
+
 bool CFrameScheduler::GetSchedule(Schedule& schedule) const
 {
   AcquireSRWLockShared(&m_lock);
@@ -276,6 +300,7 @@ bool CFrameScheduler::GetSchedule(Schedule& schedule) const
 void CFrameScheduler::ObserveFrame(uint64_t now)
 {
   AcquireSRWLockExclusive(&m_lock);
+  ++m_acquiredFrames;
   if (m_lastArrival && now > m_lastArrival)
   {
     const uint64_t interval = now - m_lastArrival;
@@ -311,8 +336,7 @@ bool CFrameScheduler::SelectFrame(uint64_t now, bool force,
   }
 
   generation = m_schedule.generation;
-  while (m_nextDeadline <= now)
-    m_nextDeadline += m_schedule.period;
+  AdvanceDeadline(now);
 
   if (force)
     m_forceNext = true;
@@ -324,11 +348,13 @@ bool CFrameScheduler::SelectFrame(uint64_t now, bool force,
   }
 
   const uint64_t safety =
-    std::max(MIN_SAFETY_NS,
-      std::max(m_guestJitter * 2, m_workEstimate / 8));
+    max(MIN_SAFETY_NS,
+      max(m_guestJitter * 2, m_workEstimate / 8));
   const uint64_t nextArrival = m_lastArrival + m_guestPeriod;
   const bool process = nextArrival <= now ||
     nextArrival + m_workEstimate + safety > m_nextDeadline;
+  if (!process)
+    ++m_skippedFrames;
   ReleaseSRWLockExclusive(&m_lock);
   return process;
 }
@@ -341,13 +367,44 @@ void CFrameScheduler::FramePublished(uint32_t generation,
   {
     m_forceNext = false;
     m_lastPublishedFrameSerial = frameSerial;
-    do
+    ++m_publishedFrames;
     m_nextDeadline += m_schedule.period;
-    while (m_nextDeadline <= now);
+    AdvanceDeadline(now);
   }
   ReleaseSRWLockExclusive(&m_lock);
 }
 
+void CFrameScheduler::LogStatistics(uint64_t now)
+{
+  AcquireSRWLockExclusive(&m_lock);
+  if (!m_scheduling || now - m_lastLog < LOG_INTERVAL_NS)
+  {
+    ReleaseSRWLockExclusive(&m_lock);
+    return;
+  }
+
+  const uint64_t acquired  = m_acquiredFrames  - m_lastLogAcquired;
+  const uint64_t skipped   = m_skippedFrames   - m_lastLogSkipped;
+  const uint64_t published = m_publishedFrames - m_lastLogPublished;
+  DEBUG_TRACE("Frame schedule owner %u: %.3f Hz client, %.3f Hz guest, "
+    "%.3f ms work, %.3f ms phase; %llu acquired, %llu skipped, "
+    "%llu published",
+    m_schedule.clientID,
+    1000000000.0 / m_schedule.period,
+    m_guestPeriod ? 1000000000.0 / m_guestPeriod : 0.0,
+    m_workEstimate / 1000000.0,
+    m_lastPhaseError / 1000000.0,
+    static_cast<unsigned long long>(acquired),
+    static_cast<unsigned long long>(skipped),
+    static_cast<unsigned long long>(published));
+
+  m_lastLog          = now;
+  m_lastLogAcquired  = m_acquiredFrames;
+  m_lastLogSkipped   = m_skippedFrames;
+  m_lastLogPublished = m_publishedFrames;
+  ReleaseSRWLockExclusive(&m_lock);
+}
+
 void CFrameScheduler::RecordFrameTiming(uint64_t duration)
 {
   if (!duration)

idd/LGIdd/CFrameScheduler.h

@@ -69,9 +69,19 @@ private:
 
   uint32_t m_lastPublishedFrameSerial = 0;
 
+  int64_t  m_lastPhaseError   = 0;
+  uint64_t m_acquiredFrames   = 0;
+  uint64_t m_skippedFrames    = 0;
+  uint64_t m_publishedFrames  = 0;
+  uint64_t m_lastLog          = 0;
+  uint64_t m_lastLogAcquired  = 0;
+  uint64_t m_lastLogSkipped   = 0;
+  uint64_t m_lastLogPublished = 0;
+
   Client * FindClient(uint32_t clientID);
   void ElectOwner(uint64_t now);
   void ApplyFeedback(Client& client, const KVMFRFrameSchedule& schedule);
+  void AdvanceDeadline(uint64_t now);
 
 public:
   static uint64_t Nanotime();
@@ -86,4 +96,5 @@ public:
   void FramePublished(uint32_t generation, uint32_t frameSerial,
     uint64_t now);
   void RecordFrameTiming(uint64_t duration);
+  void LogStatistics(uint64_t now);
 };

idd/LGIdd/CIndirectDeviceContext.cpp

@@ -1304,6 +1304,8 @@ void CIndirectDeviceContext::LGMPTimer()
     lgmpHostAckData(m_pointerQueue);
   }
 
+  m_frameScheduler.LogStatistics(now);
+
   AcquireSRWLockExclusive(&m_framePublishLock);
   if (lgmpHostQueueNewSubs(m_frameQueue))
     m_frameResendPending = true;