wayland: optionally use the presentation time protocol to measure input lag

This adds a flag, -p,--presentation-timings, that enables input lag
measuring using the presentation time Wayland protocol.

When enabled, we store a timestamp when we *send* a key to the
slave. Then, when we commit a frame for rendering to the compositor,
we request presentation feedback. We also store a timestamp for when
the frame was committed.

The 'presented' callback then looks at the input and commit
timestamps, and compares it with the presented timestamp.

The delay is logged at INFO when the delay was less than one frame
interval, at WARN when it was one frame interval, and at ERR when it
was two or more frame intervals.

We also update statistic counters that we log when foot is shut down.

config.h

@@ -34,8 +34,8 @@ struct config {
     } cursor;
 
     size_t render_worker_count;
-
     char *server_socket_path;
+    bool presentation_timings;
 };
 
 bool config_load(struct config *conf, const char *path);

input.c

@@ -374,6 +374,8 @@ keyboard_key(void *data, struct wl_keyboard *wl_keyboard, uint32_t serial,
             term_to_slave(term, buf, count);
         }
 
+        clock_gettime(
+            term->wl->presentation_clock_id, &term->render.input_time);
         term_reset_view(term);
         selection_cancel(term);
     }

main.c

@@ -90,14 +90,15 @@ main(int argc, char *const *argv)
     const char *const prog_name = argv[0];
 
     static const struct option longopts[] =  {
-        {"config",   required_argument, NULL, 'c'},
-        {"term",     required_argument, NULL, 't'},
-        {"font",     required_argument, NULL, 'f'},
-        {"geometry", required_argument, NULL, 'g'},
-        {"server",   optional_argument, NULL, 's'},
-        {"version",  no_argument,       NULL, 'v'},
-        {"help",     no_argument,       NULL, 'h'},
-        {NULL,       no_argument,       NULL,   0},
+        {"config",               required_argument, NULL, 'c'},
+        {"term",                 required_argument, NULL, 't'},
+        {"font",                 required_argument, NULL, 'f'},
+        {"geometry",             required_argument, NULL, 'g'},
+        {"server",               optional_argument, NULL, 's'},
+        {"presentation-timings", no_argument,       NULL, 'p'}, /* Undocumented */
+        {"version",              no_argument,       NULL, 'v'},
+        {"help",                 no_argument,       NULL, 'h'},
+        {NULL,                   no_argument,       NULL,   0},
     };
 
     const char *conf_path = NULL;
@@ -107,9 +108,10 @@ main(int argc, char *const *argv)
     int conf_height = -1;
     bool as_server = false;
     const char *conf_server_socket_path = NULL;
+    bool presentation_timings = false;
 
     while (true) {
-        int c = getopt_long(argc, argv, "c:tf:g:s::vh", longopts, NULL);
+        int c = getopt_long(argc, argv, "c:tf:g:s::pvh", longopts, NULL);
         if (c == -1)
             break;
 
@@ -162,6 +164,10 @@ main(int argc, char *const *argv)
                 conf_server_socket_path = optarg;
             break;
 
+        case 'p':
+            presentation_timings = true;
+            break;
+
         case 'v':
             printf("foot version %s\n", FOOT_VERSION);
             return EXIT_SUCCESS;
@@ -208,6 +214,7 @@ main(int argc, char *const *argv)
         free(conf.server_socket_path);
         conf.server_socket_path = strdup(conf_server_socket_path);
     }
+    conf.presentation_timings = presentation_timings;
 
     struct fdm *fdm = NULL;
     struct wayland *wayl = NULL;

meson.build

@@ -40,6 +40,7 @@ foreach prot : [
   wayland_protocols_datadir + '/unstable/xdg-decoration/xdg-decoration-unstable-v1.xml',
   wayland_protocols_datadir + '/unstable/xdg-output/xdg-output-unstable-v1.xml',
   wayland_protocols_datadir + '/unstable/primary-selection/primary-selection-unstable-v1.xml',
+  wayland_protocols_datadir + '/stable/presentation-time/presentation-time.xml',
   ]
 
   wl_proto_headers += custom_target(

render.c

@@ -9,6 +9,7 @@
 
 #include <wayland-cursor.h>
 #include <xdg-shell.h>
+#include <presentation-time.h>
 
 #include <fcft/fcft.h>
 
@@ -21,6 +22,112 @@
 #define min(x, y) ((x) < (y) ? (x) : (y))
 #define max(x, y) ((x) > (y) ? (x) : (y))
 
+static struct {
+    size_t total;
+    size_t zero;  /* commits presented in less than one frame interval */
+    size_t one;   /* commits presented in one frame interval */
+    size_t two;   /* commits presented in two or more frame intervals */
+} presentation_statistics = {0};
+
+static void __attribute__((destructor))
+log_presentation_statistics(void)
+{
+    if (presentation_statistics.total == 0)
+        return;
+
+    const size_t total = presentation_statistics.total;
+    LOG_INFO("presentation statistics: zero=%f%%, one=%f%%, two=%f%%",
+             100. * presentation_statistics.zero / total,
+             100. * presentation_statistics.one / total,
+             100. * presentation_statistics.two / total);
+}
+
+static void
+sync_output(void *data,
+            struct wp_presentation_feedback *wp_presentation_feedback,
+            struct wl_output *output)
+{
+}
+
+static void
+presented(void *data,
+          struct wp_presentation_feedback *wp_presentation_feedback,
+          uint32_t tv_sec_hi, uint32_t tv_sec_lo, uint32_t tv_nsec,
+          uint32_t refresh, uint32_t seq_hi, uint32_t seq_lo, uint32_t flags)
+{
+    struct terminal *term = data;
+
+    struct timeval input = {
+        .tv_sec = term->render.input_time.tv_sec,
+        .tv_usec = term->render.input_time.tv_nsec / 1000,
+    };
+
+    struct timeval commit = {
+        .tv_sec = term->render.commit_time.tv_sec,
+        .tv_usec = term->render.commit_time.tv_nsec / 1000
+    };
+
+    struct timeval presented = {
+        .tv_sec = (uint64_t)tv_sec_hi << 32 | tv_sec_lo,
+        .tv_usec = tv_nsec / 1000,
+    };
+
+    struct timeval diff = {0};
+    const char *source = NULL;
+
+    if (input.tv_sec != 0 || input.tv_usec != 0) {
+        timersub(&presented, &input, &diff);
+        source = "input";
+    } else if (commit.tv_sec != 0 || commit.tv_usec != 0) {
+        timersub(&presented, &commit, &diff);
+        source = "commit";
+    }
+
+    if (source != NULL) {
+
+        unsigned frame_count = 0;
+        if (diff.tv_sec == 0 && tll_length(term->window->on_outputs) > 0) {
+            const struct monitor *mon = tll_front(term->window->on_outputs);
+            frame_count = (double)diff.tv_usec / (1. / mon->refresh * 1000000.);
+        }
+
+        presentation_statistics.total++;
+        if (frame_count >= 2)
+            presentation_statistics.two++;
+        else if (frame_count >= 1)
+            presentation_statistics.one++;
+        else
+            presentation_statistics.zero++;
+
+        #define _log_fmt "%s to screen time: %lus %luµs (more than %u frames)"
+
+        if (frame_count >= 2)
+            LOG_ERR(_log_fmt, source, diff.tv_sec, diff.tv_usec, frame_count);
+        else if (frame_count >= 1)
+            LOG_WARN(_log_fmt, source, diff.tv_sec, diff.tv_usec, frame_count);
+        else
+            LOG_INFO(_log_fmt, source, diff.tv_sec, diff.tv_usec, frame_count);
+
+        #undef _log_fmt
+    }
+
+    wp_presentation_feedback_destroy(wp_presentation_feedback);
+    memset(&term->render.input_time, 0, sizeof(term->render.input_time));
+    memset(&term->render.commit_time, 0, sizeof(term->render.commit_time));
+}
+
+static void
+discarded(void *data, struct wp_presentation_feedback *wp_presentation_feedback)
+{
+    wp_presentation_feedback_destroy(wp_presentation_feedback);
+}
+
+static const struct wp_presentation_feedback_listener presentation_feedback_listener = {
+    .sync_output = &sync_output,
+    .presented = &presented,
+    .discarded = &discarded,
+};
+
 struct font *
 attrs_to_font(const struct terminal *term, const struct attributes *attrs)
 {
@@ -697,6 +804,22 @@ grid_render(struct terminal *term)
     wl_callback_add_listener(term->window->frame_callback, &frame_listener, term);
 
     wl_surface_set_buffer_scale(term->window->surface, term->scale);
+
+
+    if (term->wl->presentation != NULL && term->render.presentation_timings) {
+        clock_gettime(term->wl->presentation_clock_id, &term->render.commit_time);
+
+        struct wp_presentation_feedback *feedback = wp_presentation_feedback(
+            term->wl->presentation, term->window->surface);
+
+        if (feedback == NULL) {
+            LOG_WARN("failed to create presentation feedback");
+        } else {
+            wp_presentation_feedback_add_listener(
+                feedback, &presentation_feedback_listener, term);
+        }
+    }
+
     wl_surface_commit(term->window->surface);
 
 #if TIME_FRAME_RENDERING

terminal.c

@@ -370,6 +370,11 @@ fdm_delayed_render(struct fdm *fdm, int fd, int events, void *data)
         return false;
     }
 
+    if (ret1 > 0)
+        LOG_DBG("lower delay timer expired");
+    else if (ret2 > 0)
+        LOG_DBG("upper delay timer expired");
+
     render_refresh(term);
 
     /* Reset timers */
@@ -593,6 +598,7 @@ term_init(const struct config *conf, struct fdm *fdm, struct wayland *wayl,
                 .count = conf->render_worker_count,
                 .queue = tll_init(),
             },
+            .presentation_timings = conf->presentation_timings,
         },
         .delayed_render_timer = {
             .is_armed = false,

terminal.h

@@ -302,6 +302,10 @@ struct terminal {
         struct buffer *last_buf;     /* Buffer we rendered to last time */
         bool was_flashing;           /* Flash was active last time we rendered */
         bool was_searching;
+
+        bool presentation_timings;
+        struct timespec input_time;
+        struct timespec commit_time;
     } render;
 
     /* Temporary: for FDM */

wayland.c

@@ -199,6 +199,20 @@ static struct zxdg_output_v1_listener xdg_output_listener = {
     .description = xdg_output_handle_description,
 };
 
+static void
+clock_id(void *data, struct wp_presentation *wp_presentation, uint32_t clk_id)
+{
+    struct wayland *wayl = data;
+    wayl->presentation_clock_id = clk_id;
+
+    LOG_DBG("presentation clock ID: %u", clk_id);
+}
+
+static const struct wp_presentation_listener presentation_listener = {
+    .clock_id = &clock_id,
+};
+
+
 static bool
 verify_iface_version(const char *iface, uint32_t version, uint32_t wanted)
 {
@@ -326,6 +340,17 @@ handle_global(void *data, struct wl_registry *registry,
             wayl->registry, name,
             &zwp_primary_selection_device_manager_v1_interface, required);
     }
+
+    else if (strcmp(interface, wp_presentation_interface.name) == 0) {
+        const uint32_t required = 1;
+        if (!verify_iface_version(interface, version, required))
+            return;
+
+        wayl->presentation = wl_registry_bind(
+            wayl->registry, name, &wp_presentation_interface, required);
+        wp_presentation_add_listener(
+            wayl->presentation, &presentation_listener, wayl);
+    }
 }
 
 static void
@@ -658,6 +683,9 @@ wayl_destroy(struct wayland *wayl)
     if (wayl->xdg_decoration_manager != NULL)
         zxdg_decoration_manager_v1_destroy(wayl->xdg_decoration_manager);
 
+    if (wayl->presentation != NULL)
+        wp_presentation_destroy(wayl->presentation);
+
     if (wayl->kbd.xkb_compose_state != NULL)
         xkb_compose_state_unref(wayl->kbd.xkb_compose_state);
     if (wayl->kbd.xkb_compose_table != NULL)

wayland.h

@@ -6,9 +6,11 @@
 #include <sys/time.h>
 
 #include <wayland-client.h>
-#include <primary-selection-unstable-v1.h>
 #include <xkbcommon/xkbcommon.h>
 
+#include <primary-selection-unstable-v1.h>
+#include <presentation-time.h>
+
 #include <tllist.h>
 
 #include "fdm.h"
@@ -114,6 +116,9 @@ struct wayland {
     struct xdg_wm_base *shell;
     struct zxdg_decoration_manager_v1 *xdg_decoration_manager;
 
+    struct wp_presentation *presentation;
+    uint32_t presentation_clock_id;
+
     /* Keyboard */
     struct kbd kbd;