From 5a074190960130b6136a398d83da43fd1e8ec7e2 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Daniel=20Ekl=C3=B6f?= Date: Tue, 31 Dec 2019 15:39:40 +0100 Subject: [PATCH] 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 | 2 +- input.c | 2 + main.c | 25 +++++++---- meson.build | 1 + render.c | 123 ++++++++++++++++++++++++++++++++++++++++++++++++++++ terminal.c | 6 +++ terminal.h | 4 ++ wayland.c | 28 ++++++++++++ wayland.h | 7 ++- 9 files changed, 187 insertions(+), 11 deletions(-) diff --git a/config.h b/config.h index bc28fa51..30e18f25 100644 --- a/config.h +++ b/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); diff --git a/input.c b/input.c index ca7d0ec2..fd15b392 100644 --- a/input.c +++ b/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); } diff --git a/main.c b/main.c index da6bc0b7..7f5f935c 100644 --- a/main.c +++ b/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; diff --git a/meson.build b/meson.build index 5169de73..786ab7c9 100644 --- a/meson.build +++ b/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( diff --git a/render.c b/render.c index daf4aeaa..61220414 100644 --- a/render.c +++ b/render.c @@ -9,6 +9,7 @@ #include #include +#include #include @@ -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 diff --git a/terminal.c b/terminal.c index eb87661c..61c3fdfa 100644 --- a/terminal.c +++ b/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, diff --git a/terminal.h b/terminal.h index 0db97e2b..a1c01942 100644 --- a/terminal.h +++ b/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 */ diff --git a/wayland.c b/wayland.c index 147d5f68..6b4287bf 100644 --- a/wayland.c +++ b/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) diff --git a/wayland.h b/wayland.h index 3f5212c5..575254e9 100644 --- a/wayland.h +++ b/wayland.h @@ -6,9 +6,11 @@ #include #include -#include #include +#include +#include + #include #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;