[client] metrics: correlate Wayland presentation timing

client/displayservers/Wayland/gl.c

@@ -28,6 +28,7 @@
 
 #include "app.h"
 #include "common/debug.h"
+#include "common/time.h"
 #include "util.h"
 
 #if defined(ENABLE_EGL) || defined(ENABLE_OPENGL)
@@ -229,9 +230,12 @@ static const struct wp_image_description_v1_listener hdrImageDescListener =
 };
 
 bool waylandEGLSwapBuffers(EGLDisplay display, EGLSurface surface,
-    const struct Rect * damage, int count)
+    const struct Rect * damage, int count, uint64_t frameToken,
+    uint64_t * swapTime, bool * presentTracked)
 {
   bool result     = false;
+  *swapTime       = 0;
+  *presentTracked = false;
 
   // EGL presentation sends a batch of Wayland requests ending in a surface
   // commit. A concurrent commit would apply a partial batch and, when explicit
@@ -249,10 +253,15 @@ bool waylandEGLSwapBuffers(EGLDisplay display, EGLSurface surface,
         swapWithDamageInit(&wlWm.swapWithDamage, display);
     }
 
-    waylandPresentationFrame();
+    struct WaylandPresentationFrame * presentationFrame =
+      waylandPresentationFrame(frameToken);
     applyHDRPending();
+    const uint64_t swapStart  = nanotime();
     result = swapWithDamage(
         &wlWm.swapWithDamage, display, surface, damage, count);
+    *swapTime = nanotime() - swapStart;
+    waylandPresentationSwapDone(
+        presentationFrame, result, presentTracked);
     if (result)
       activateReadyHDRImageDesc();
   });
@@ -756,6 +765,9 @@ void waylandGLSetSwapInterval(int interval)
 
 void waylandGLSwapBuffers(void)
 {
-  (void)waylandEGLSwapBuffers(wlWm.glDisplay, wlWm.glSurface, NULL, 0);
+  uint64_t swapTime       = 0;
+  bool     presentTracked = false;
+  (void)waylandEGLSwapBuffers(wlWm.glDisplay, wlWm.glSurface, NULL, 0, 0,
+      &swapTime, &presentTracked);
 }
 #endif

client/displayservers/Wayland/presentation.c

@@ -30,11 +30,77 @@
 #include "common/debug.h"
 #include "common/time.h"
 
-struct FrameData
+struct WaylandPresentationFrame
 {
+  atomic_uint                      refs;
+  struct wl_list                   link;
+  struct wp_presentation_feedback * feedback;
+  uint64_t                         frameToken;
   struct timespec                  sent;
+  struct timespec                  swapReturn;
+  struct timespec                  presented;
+  bool                             swapDone;
+  bool                             swapValid;
+  bool                             feedbackDone;
+  bool                             feedbackValid;
+  bool                             timingComplete;
 };
 
+struct PresentationCompletion
+{
+  uint64_t frameToken;
+  uint64_t presentTime;
+  bool     notify;
+  bool     valid;
+};
+
+static void presentationFrameRelease(struct WaylandPresentationFrame * frame)
+{
+  if (atomic_fetch_sub_explicit(
+        &frame->refs, 1, memory_order_acq_rel) == 1)
+    free(frame);
+}
+
+static bool presentationOrdered(const struct timespec * left,
+    const struct timespec * right)
+{
+  return left->tv_sec > right->tv_sec ||
+    (left->tv_sec == right->tv_sec && left->tv_nsec >= right->tv_nsec);
+}
+
+static uint64_t presentationDelta(const struct timespec * left,
+    const struct timespec * right)
+{
+  struct timespec delta;
+  tsDiff(&delta, left, right);
+  return (uint64_t)delta.tv_sec * 1000000000ULL + delta.tv_nsec;
+}
+
+static void presentationCompleteLocked(
+    struct WaylandPresentationFrame * frame,
+    struct PresentationCompletion * completion)
+{
+  if (frame->timingComplete || !frame->swapDone || !frame->feedbackDone)
+    return;
+
+  frame->timingComplete   = true;
+  completion->notify      = frame->frameToken != 0;
+  completion->frameToken = frame->frameToken;
+  completion->valid      = frame->swapValid && frame->feedbackValid &&
+    presentationOrdered(&frame->presented, &frame->swapReturn);
+  if (completion->valid)
+    completion->presentTime = presentationDelta(
+        &frame->presented, &frame->swapReturn);
+}
+
+static void presentationNotify(
+    const struct PresentationCompletion * completion)
+{
+  if (completion->notify)
+    app_handleFramePresented(completion->frameToken,
+        completion->presentTime, completion->valid);
+}
+
 static void presentationClockId(void * data,
     struct wp_presentation * presentation, uint32_t clkId)
 {
@@ -57,18 +123,34 @@ static void presentationFeedbackPresented(void * opaque,
     struct wp_presentation_feedback * feedback, uint32_t tvSecHi, uint32_t tvSecLo,
     uint32_t tvNsec, uint32_t refresh, uint32_t seqHi, uint32_t seqLo, uint32_t flags)
 {
-  struct FrameData * data = opaque;
-  struct timespec present = {
+  struct WaylandPresentationFrame * frame = opaque;
+  const struct timespec present = {
     .tv_sec = (uint64_t) tvSecHi << 32 | tvSecLo,
     .tv_nsec = tvNsec,
   };
-  struct timespec delta;
+  struct PresentationCompletion completion = {};
 
-  tsDiff(&delta, &present, &data->sent);
+  if (tvNsec < 1000000000)
+  {
+    struct timespec delta;
+    tsDiff(&delta, &present, &frame->sent);
     ringbuffer_push(wlWm.photonTimings,
         &(float){ delta.tv_sec * 1e3f + delta.tv_nsec * 1e-6f });
-  free(data);
+  }
+
+  INTERLOCKED_SECTION(wlWm.presentationLock,
+  {
+    wl_list_remove(&frame->link);
+    frame->feedback      = NULL;
+    frame->feedbackDone  = true;
+    frame->feedbackValid = tvNsec < 1000000000;
+    frame->presented     = present;
+    presentationCompleteLocked(frame, &completion);
+  });
+
+  presentationNotify(&completion);
   wp_presentation_feedback_destroy(feedback);
+  presentationFrameRelease(frame);
 }
 
 bool waylandGetFramePeriod(uint64_t * period)
@@ -82,8 +164,21 @@ bool waylandGetFramePeriod(uint64_t * period)
 static void presentationFeedbackDiscarded(void * data,
     struct wp_presentation_feedback * feedback)
 {
-  free(data);
+  struct WaylandPresentationFrame * frame = data;
+  struct PresentationCompletion completion = {};
+
+  INTERLOCKED_SECTION(wlWm.presentationLock,
+  {
+    wl_list_remove(&frame->link);
+    frame->feedback      = NULL;
+    frame->feedbackDone  = true;
+    frame->feedbackValid = false;
+    presentationCompleteLocked(frame, &completion);
+  });
+
+  presentationNotify(&completion);
   wp_presentation_feedback_destroy(feedback);
+  presentationFrameRelease(frame);
 }
 
 static const struct wp_presentation_feedback_listener presentationFeedbackListener = {
@@ -94,10 +189,13 @@ static const struct wp_presentation_feedback_listener presentationFeedbackListen
 
 bool waylandPresentationInit(void)
 {
-  if (wlWm.presentation)
-  {
+  LG_LOCK_INIT(wlWm.presentationLock);
+  wl_list_init(&wlWm.presentationFrames);
   atomic_store_explicit(
       &wlWm.presentationClockValid, false, memory_order_release);
+
+  if (wlWm.presentation)
+  {
     wlWm.photonTimings = ringbuffer_new(256, sizeof(float));
     wlWm.photonGraph   = app_registerGraph("PHOTON", wlWm.photonTimings,
         0.0f, 30.0f, NULL);
@@ -109,36 +207,129 @@ bool waylandPresentationInit(void)
 
 void waylandPresentationFree(void)
 {
-  if (!wlWm.presentation)
-    return;
-
   atomic_store_explicit(
       &wlWm.presentationClockValid, false, memory_order_release);
+
+  for (;;)
+  {
+    struct WaylandPresentationFrame * frame = NULL;
+    struct wp_presentation_feedback * feedback = NULL;
+    struct PresentationCompletion      completion = {};
+
+    LG_LOCK(wlWm.presentationLock);
+    if (!wl_list_empty(&wlWm.presentationFrames))
+    {
+      frame = wl_container_of(
+          wlWm.presentationFrames.next, frame, link);
+      wl_list_remove(&frame->link);
+      feedback             = frame->feedback;
+      frame->feedback      = NULL;
+      frame->swapDone      = true;
+      frame->swapValid     = false;
+      frame->feedbackDone  = true;
+      frame->feedbackValid = false;
+      presentationCompleteLocked(frame, &completion);
+    }
+    LG_UNLOCK(wlWm.presentationLock);
+
+    if (!frame)
+      break;
+
+    presentationNotify(&completion);
+    wp_presentation_feedback_destroy(feedback);
+    presentationFrameRelease(frame);
+  }
+
+  if (wlWm.presentation)
+  {
     wp_presentation_destroy(wlWm.presentation);
+    wlWm.presentation = NULL;
     app_unregisterGraph(wlWm.photonGraph);
     ringbuffer_free(&wlWm.photonTimings);
+  }
+  LG_LOCK_FREE(wlWm.presentationLock);
 }
 
-void waylandPresentationFrame(void)
+struct WaylandPresentationFrame * waylandPresentationFrame(
+    uint64_t frameToken)
 {
   if (!wlWm.presentation || !atomic_load_explicit(
         &wlWm.presentationClockValid, memory_order_acquire))
-    return;
+    return NULL;
 
-  struct FrameData * data = malloc(sizeof(*data));
-  if (!data)
+  struct WaylandPresentationFrame * frame = calloc(1, sizeof(*frame));
+  if (!frame)
   {
     DEBUG_ERROR("out of memory");
-    return;
+    return NULL;
   }
 
-  if (clock_gettime(wlWm.clkId, &data->sent))
+  if (clock_gettime(wlWm.clkId, &frame->sent))
   {
-    DEBUG_ERROR("clock_gettime failed: %s\n", strerror(errno));
-    free(data);
-    return;
+    DEBUG_ERROR("clock_gettime failed: %s", strerror(errno));
+    free(frame);
+    return NULL;
   }
 
-  struct wp_presentation_feedback * feedback = wp_presentation_feedback(wlWm.presentation, wlWm.surface);
-  wp_presentation_feedback_add_listener(feedback, &presentationFeedbackListener, data);
+  frame->feedback =
+    wp_presentation_feedback(wlWm.presentation, wlWm.surface);
+  if (!frame->feedback)
+  {
+    free(frame);
+    return NULL;
+  }
+
+  frame->frameToken     = frameToken;
+  frame->timingComplete = frameToken == 0;
+  atomic_init(&frame->refs, 2);
+  if (wp_presentation_feedback_add_listener(frame->feedback,
+        &presentationFeedbackListener, frame) < 0)
+  {
+    wp_presentation_feedback_destroy(frame->feedback);
+    free(frame);
+    return NULL;
+  }
+
+  INTERLOCKED_SECTION(wlWm.presentationLock,
+  {
+    wl_list_insert(&wlWm.presentationFrames, &frame->link);
+  });
+  return frame;
+}
+
+void waylandPresentationSwapDone(struct WaylandPresentationFrame * frame,
+    bool result, bool * presentTracked)
+{
+  *presentTracked = false;
+  if (!frame)
+    return;
+
+  struct timespec swapReturn = {};
+  const bool      swapValid  = result &&
+    clock_gettime(wlWm.clkId, &swapReturn) == 0;
+  if (result && !swapValid)
+    DEBUG_ERROR("clock_gettime failed: %s", strerror(errno));
+
+  struct PresentationCompletion completion = {};
+  INTERLOCKED_SECTION(wlWm.presentationLock,
+  {
+    frame->swapDone   = true;
+    frame->swapValid  = swapValid;
+    frame->swapReturn = swapReturn;
+
+    if (!swapValid && !frame->timingComplete)
+    {
+      frame->timingComplete  = true;
+      completion.notify      = true;
+      completion.frameToken  = frame->frameToken;
+      completion.presentTime = 0;
+      completion.valid       = false;
+    }
+    else
+      presentationCompleteLocked(frame, &completion);
+  });
+
+  *presentTracked = result && frame->frameToken != 0;
+  presentationNotify(&completion);
+  presentationFrameRelease(frame);
 }

client/displayservers/Wayland/wayland.c

@@ -207,8 +207,8 @@ static void waylandShutdown(void)
 static void waylandFree(void)
 {
   waylandIdleFree();
-  waylandWindowFree();
   waylandPresentationFree();
+  waylandWindowFree();
   waylandInputFree();
   waylandOutputFree();
   waylandColorMgmtFree();

client/displayservers/Wayland/wayland.h

@@ -162,6 +162,8 @@ struct WaylandDSState
   struct wp_presentation * presentation;
   clockid_t                clkId;
   _Atomic(bool)            presentationClockValid;
+  LG_Lock                  presentationLock;
+  struct wl_list           presentationFrames;
   _Atomic(uint64_t)        nominalPeriod;
   RingBuffer               photonTimings;
   GraphHandle              photonGraph;
@@ -336,7 +338,8 @@ void waylandCursorScaleChange(void);
 bool waylandEGLInit(int w, int h);
 EGLDisplay waylandGetEGLDisplay(void);
 bool waylandEGLSwapBuffers(EGLDisplay display, EGLSurface surface,
-    const struct Rect * damage, int count);
+    const struct Rect * damage, int count, uint64_t frameToken,
+    uint64_t * swapTime, bool * presentTracked);
 #endif
 
 #ifdef ENABLE_EGL
@@ -410,8 +413,12 @@ bool waylandPollRegister(int fd, WaylandPollCallback callback, void * opaque, ui
 bool waylandPollUnregister(int fd);
 
 // presentation module
+struct WaylandPresentationFrame;
 bool waylandPresentationInit(void);
-void waylandPresentationFrame(void);
+struct WaylandPresentationFrame * waylandPresentationFrame(
+    uint64_t frameToken);
+void waylandPresentationSwapDone(struct WaylandPresentationFrame * frame,
+    bool result, bool * presentTracked);
 void waylandPresentationFree(void);
 bool waylandGetFramePeriod(uint64_t * period);
 

client/displayservers/X11/x11.c

@@ -1661,13 +1661,20 @@ static EGLNativeWindowType x11GetEGLNativeWindow(void)
 }
 
 static bool x11EGLSwapBuffers(EGLDisplay display, EGLSurface surface,
-    const struct Rect * damage, int count)
+    const struct Rect * damage, int count, uint64_t frameToken,
+    uint64_t * swapTime, bool * presentTracked)
 {
   static struct SwapWithDamageData data = {0};
   if (!data.init)
     swapWithDamageInit(&data, display);
 
-  return swapWithDamage(&data, display, surface, damage, count);
+  (void)frameToken;
+  *presentTracked       = false;
+  const uint64_t start  = nanotime();
+  const bool     result =
+    swapWithDamage(&data, display, surface, damage, count);
+  *swapTime = nanotime() - start;
+  return result;
 }
 #endif
 

client/include/app.h

@@ -88,6 +88,8 @@ void app_handleGrabEvent(bool active);
 void app_handleFocusEvent(bool focused);
 void app_handleCloseEvent(void);
 void app_handleRenderEvent(const uint64_t timeUs);
+void app_handleFramePresented(uint64_t frameToken, uint64_t presentTime,
+    bool valid);
 
 void app_setFullscreen(bool fs);
 bool app_getFullscreen(void);
@@ -104,7 +106,8 @@ bool app_getHDRDescFailed(void);
 EGLDisplay app_getEGLDisplay(void);
 EGLNativeWindowType app_getEGLNativeWindow(void);
 bool app_eglSwapBuffers(EGLDisplay display, EGLSurface surface,
-    const struct Rect * damage, int count);
+    const struct Rect * damage, int count, uint64_t frameToken,
+    uint64_t * swapTime, bool * presentTracked);
 #endif
 
 #ifdef ENABLE_OPENGL

client/include/interface/displayserver.h

@@ -181,7 +181,8 @@ struct LG_DisplayServerOps
   EGLDisplay (*getEGLDisplay)(void);
   EGLNativeWindowType (*getEGLNativeWindow)(void);
   bool (*eglSwapBuffers)(EGLDisplay display, EGLSurface surface,
-      const struct Rect * damage, int count);
+      const struct Rect * damage, int count, uint64_t frameToken,
+      uint64_t * swapTime, bool * presentTracked);
 #endif
 
 #ifdef ENABLE_OPENGL

client/include/interface/renderer.h

@@ -148,7 +148,8 @@ typedef struct LG_RendererFrameTiming
   uint64_t              effectsTime; /* post-processing work */
   uint64_t              desktopTime; /* desktop work, excluding effects */
   uint64_t              composeTime; /* composition, excluding UI overlay */
-  uint64_t              swapTime;    /* display-server buffer swap */
+  uint64_t              swapTime;    /* actual EGL buffer swap */
+  bool                  presentTracked; /* presentation feedback expected */
 }
 LG_RendererFrameTiming;
 

client/renderers/EGL/egl.c

@@ -1689,12 +1689,10 @@ static bool egl_render(LG_Renderer * renderer, LG_RendererRotate rotate,
   const uint64_t composeEnd = nanotime();
   timing->composeTime += composeEnd - postOverlayStart;
 
-  const uint64_t swapStart  = nanotime();
   const bool     swapResult = app_eglSwapBuffers(
       this->display, this->surface, damage,
-      this->noSwapDamage ? 0 : damageIdx);
-  const uint64_t swapEnd    = nanotime();
-  timing->swapTime = swapEnd - swapStart;
+      this->noSwapDamage ? 0 : damageIdx, timing->frameToken,
+      &timing->swapTime, &timing->presentTracked);
 
   if (!swapResult)
     DEBUG_ERROR("Failed to swap EGL buffers (eglError: 0x%x)", eglGetError());

client/src/app.c

@@ -839,9 +839,11 @@ EGLNativeWindowType app_getEGLNativeWindow(void)
 }
 
 bool app_eglSwapBuffers(EGLDisplay display, EGLSurface surface,
-    const struct Rect * damage, int count)
+    const struct Rect * damage, int count, uint64_t frameToken,
+    uint64_t * swapTime, bool * presentTracked)
 {
-  return g_state.ds->eglSwapBuffers(display, surface, damage, count);
+  return g_state.ds->eglSwapBuffers(display, surface, damage, count,
+      frameToken, swapTime, presentTracked);
 }
 #endif
 

client/src/main.c

@@ -204,11 +204,13 @@ static bool tickTimerFn(void * unused)
 
 #define FRAME_TIMING_RECORD_COUNT       1024
 #define FRAME_TIMING_PUBLISH_BATCH_SIZE 32
+#define FRAME_TIMING_PRESENT_TIMEOUT_NS 500000000ULL
 
 enum FrameTimingReady
 {
   FRAME_TIMING_FRAME_READY   = 1 << 0,
   FRAME_TIMING_RENDER_READY  = 1 << 1,
+  FRAME_TIMING_PRESENT_READY = 1 << 2,
 };
 
 struct FrameTimingRecord
@@ -222,6 +224,7 @@ struct FrameTimingRecord
   bool                  producerValid;
   bool                  phaseValid;
   bool                  transportValid;
+  bool                  presentValid;
 
   uint64_t captureTime;
   uint64_t postProcessTime;
@@ -242,6 +245,8 @@ struct FrameTimingRecord
   uint64_t desktopTime;
   uint64_t composeTime;
   uint64_t swapTime;
+  uint64_t presentTime;
+  uint64_t presentDeadline;
 };
 
 static struct
@@ -300,6 +305,23 @@ static struct FrameTimingRecord * frameTimingRecord(
     (token - 1) % FRAME_TIMING_RECORD_COUNT];
 }
 
+void app_handleFramePresented(uint64_t frameToken, uint64_t presentTime,
+    bool valid)
+{
+  if (!frameToken)
+    return;
+
+  INTERLOCKED_SECTION(l_frameTiming.lock, {
+    struct FrameTimingRecord * record = frameTimingRecord(frameToken);
+    if (record->token == frameToken)
+    {
+      record->presentTime  = presentTime;
+      record->presentValid = valid;
+      record->readyMask   |= FRAME_TIMING_PRESENT_READY;
+    }
+  });
+}
+
 static LG_RendererFrameToken frameTimingReserve(void)
 {
   LG_RendererFrameToken token;
@@ -425,6 +447,14 @@ static void frameTimingFinishRender(const LG_RendererFrameTiming * timing,
     record->desktopTime     = timing->desktopTime;
     record->composeTime     = timing->composeTime;
     record->swapTime        = timing->swapTime;
+    record->presentDeadline = timestamp + FRAME_TIMING_PRESENT_TIMEOUT_NS;
+    if (!timing->presentTracked &&
+        !(record->readyMask & FRAME_TIMING_PRESENT_READY))
+    {
+      record->presentTime  = 0;
+      record->presentValid = false;
+      record->readyMask   |= FRAME_TIMING_PRESENT_READY;
+    }
     record->readyMask |= FRAME_TIMING_RENDER_READY;
 
     record->transportValid = record->phaseValid &&
@@ -474,6 +504,7 @@ static void frameTimingPublishReady(void)
   unsigned                 readyCount = 0;
 
   LG_LOCK(l_frameTiming.lock);
+  const uint64_t now = nanotime();
   while (readyCount < FRAME_TIMING_PUBLISH_BATCH_SIZE &&
       l_frameTiming.publishCount)
   {
@@ -493,6 +524,16 @@ static void frameTimingPublishReady(void)
     if (!(record->readyMask & FRAME_TIMING_FRAME_READY))
       break;
 
+    if (!(record->readyMask & FRAME_TIMING_PRESENT_READY))
+    {
+      if (!record->presentDeadline || now < record->presentDeadline)
+        break;
+
+      record->presentTime  = 0;
+      record->presentValid = false;
+      record->readyMask   |= FRAME_TIMING_PRESENT_READY;
+    }
+
     ready[readyCount++] = *record;
     *record = (struct FrameTimingRecord) {};
     l_frameTiming.publishRead =
@@ -513,12 +554,13 @@ static void frameTimingPublishReady(void)
       record->readyLeadTime > transportAccounted ?
       record->readyLeadTime - transportAccounted : 0;
     uint32_t                         validMask =
-      OVERLAY_FRAME_TIMING_VALID_ALL &
-      ~OVERLAY_FRAME_TIMING_VALID_PRESENT;
+      OVERLAY_FRAME_TIMING_VALID_ALL;
     if (!record->producerValid)
       validMask &= ~OVERLAY_FRAME_TIMING_VALID_PRODUCER;
     if (!record->producerValid || !record->transportValid)
       validMask &= ~OVERLAY_FRAME_TIMING_VALID_TRANSPORT;
+    if (!record->presentValid)
+      validMask &= ~OVERLAY_FRAME_TIMING_VALID_PRESENT;
 
     const OverlayFrameTiming         timing = {
       .timestamp   = record->timestamp,
@@ -539,7 +581,7 @@ static void frameTimingPublishReady(void)
       .desktop     = record->desktopTime     * 1e-6f,
       .compose     = record->composeTime     * 1e-6f,
       .swap        = record->swapTime        * 1e-6f,
-      .present     = 0.0f,
+      .present     = record->presentTime     * 1e-6f,
     };
     ringbuffer_push(g_state.frameLatency, &timing);
   }