evdev: warn if our event processing lags by 10ms or more

Take a snapshot of the time every 10 libinput_dispatch() calls. During event
processing, check if the event timestamp is more than 10ms in the past and
warn if it is. This should provide a warning to users when the compositor is
too slow to processes events but events aren't coming in fast enough to
trigger SYN_DROPPED.

Because we check the device event time against the dispatch time we may get
warnings for multiple devices on delayed processing. This is intended, it's
good to know which devices were affected.

In the test suite we need to ignore the warning though, since we compose the
events in very specific ways it's common to exceed that threshold
(particularly when calling litest_touch_move_to).

Signed-off-by: Peter Hutterer <peter.hutterer@who-t.net>

src/evdev.c

@@ -1018,6 +1018,31 @@ evdev_sync_device(struct evdev_device *device)
 	return rc == -EAGAIN ? 0 : rc;
 }
 
+static inline void
+evdev_note_time_delay(struct evdev_device *device,
+		      const struct input_event *ev)
+{
+	struct libinput *libinput = evdev_libinput_context(device);
+	uint32_t tdelta;
+
+	/* if we have a current libinput_dispatch() snapshot, compare our
+	 * event time with the one from the snapshot. If we have more than
+	 * 10ms delay, complain about it. This catches delays in processing
+	 * where there is no steady event flow and thus SYN_DROPPED may not
+	 * get hit by the kernel despite us being too slow.
+	 */
+	if (libinput->dispatch_time == 0)
+		return;
+
+	tdelta = us2ms(libinput->dispatch_time - input_event_time(ev));
+	if (tdelta > 10) {
+		evdev_log_bug_client_ratelimit(device,
+					       &device->delay_warning_limit,
+					       "event processing lagging behind by %dms, your system is too slow\n",
+					       tdelta);
+	}
+}
+
 static void
 evdev_device_dispatch(void *data)
 {
@@ -1025,6 +1050,7 @@ evdev_device_dispatch(void *data)
 	struct libinput *libinput = evdev_libinput_context(device);
 	struct input_event ev;
 	int rc;
+	bool once = false;
 
 	/* If the compositor is repainting, this function is called only once
 	 * per frame and we have to process all the events available on the
@@ -1047,6 +1073,10 @@ evdev_device_dispatch(void *data)
 			if (rc == 0)
 				rc = LIBEVDEV_READ_STATUS_SUCCESS;
 		} else if (rc == LIBEVDEV_READ_STATUS_SUCCESS) {
+			if (!once) {
+				evdev_note_time_delay(device, &ev);
+				once = true;
+			}
 			evdev_device_dispatch_one(device, &ev);
 		}
 	} while (rc == LIBEVDEV_READ_STATUS_SUCCESS);
@@ -2208,6 +2238,8 @@ evdev_device_create(struct libinput_seat *seat,
 
 	/* at most 5 SYN_DROPPED log-messages per 30s */
 	ratelimit_init(&device->syn_drop_limit, s2us(30), 5);
+	/* at most 5 "delayed processing" log messages per minute */
+	ratelimit_init(&device->delay_warning_limit, s2us(60), 5);
 	/* at most 5 log-messages per 5s */
 	ratelimit_init(&device->nonpointer_rel_limit, s2us(5), 5);
 

src/evdev.h

@@ -179,6 +179,7 @@ struct evdev_device {
 	double trackpoint_multiplier; /* trackpoint constant multiplier */
 	bool use_velocity_averaging; /* whether averaging should be applied on velocity calculation */
 	struct ratelimit syn_drop_limit; /* ratelimit for SYN_DROPPED logging */
+	struct ratelimit delay_warning_limit; /* ratelimit for delayd processing logging */
 	struct ratelimit nonpointer_rel_limit; /* ratelimit for REL_* events from non-pointer devices */
 	uint32_t model_flags;
 	struct mtdev *mtdev;

src/libinput-private.h

@@ -156,6 +156,7 @@ struct libinput {
 	struct list device_group_list;
 
 	uint64_t last_event_time;
+	uint64_t dispatch_time;
 
 	bool quirks_initialized;
 	struct quirks_context *quirks;

src/libinput.c

@@ -2100,10 +2100,19 @@ libinput_get_fd(struct libinput *libinput)
 LIBINPUT_EXPORT int
 libinput_dispatch(struct libinput *libinput)
 {
+	static uint8_t take_time_snapshot;
 	struct libinput_source *source;
 	struct epoll_event ep[32];
 	int i, count;
 
+	/* Every 10 calls to libinput_dispatch() we take the current time so
+	 * we can check the delay between our current time and the event
+	 * timestamps */
+	if ((++take_time_snapshot % 10) == 0)
+		libinput->dispatch_time = libinput_now(libinput);
+	else if (libinput->dispatch_time)
+		libinput->dispatch_time = 0;
+
 	count = epoll_wait(libinput->epoll_fd, ep, ARRAY_LENGTH(ep), 0);
 	if (count < 0)
 		return -errno;

test/litest.c

@@ -677,9 +677,14 @@ litest_log_handler(struct libinput *libinput,
 		/* valgrind is too slow and some of our offsets are too
 		 * short, don't abort if during a valgrind run we get a
 		 * negative offset */
-		if ((!RUNNING_ON_VALGRIND && !in_debugger) ||
+		if ((RUNNING_ON_VALGRIND && in_debugger) ||
-		    !strstr(format, "your system is too slow"))
+		    !strstr(format, "scheduled expiry is in the past")) {
-		litest_abort_msg("libinput bug triggered, aborting.\n");
+			/* noop */
+		} else if (!strstr(format, "event processing lagging behind")) {
+			/* noop */
+		} else {
+			litest_abort_msg("libinput bug triggered, aborting.\n");
+		}
 	}
 
 	if (strstr(format, "Touch jump detected and discarded")) {

test/test-misc.c

@@ -688,6 +688,43 @@ START_TEST(timer_offset_bug_warning)
 }
 END_TEST
 
+static void timer_delay_warning(struct libinput *libinput,
+				enum libinput_log_priority priority,
+				const char *format,
+				va_list args)
+{
+	int *warning_triggered = (int*)libinput_get_user_data(libinput);
+
+	if (priority == LIBINPUT_LOG_PRIORITY_ERROR &&
+	    strstr(format, "event processing lagging behind by"))
+		(*warning_triggered)++;
+}
+
+
+START_TEST(timer_delay_bug_warning)
+{
+	struct litest_device *dev = litest_current_device();
+	struct libinput *li = dev->libinput;
+	int warning_triggered = 0;
+
+	litest_drain_events(li);
+
+	for (int i = 0; i < 10; i++) {
+		litest_button_click(dev, BTN_LEFT, true);
+		libinput_dispatch(li);
+		litest_button_click(dev, BTN_LEFT, false);
+		msleep(11);
+
+		libinput_set_user_data(li, &warning_triggered);
+		libinput_log_set_handler(li, timer_delay_warning);
+		libinput_dispatch(li);
+	}
+
+	ck_assert_int_ge(warning_triggered, 1);
+	litest_restore_log_handler(li);
+}
+END_TEST
+
 START_TEST(timer_flush)
 {
 	struct libinput *li;
@@ -855,6 +892,7 @@ TEST_COLLECTION(misc)
 	litest_add_deviceless("config:status string", config_status_string);
 
 	litest_add_for_device("timer:offset-warning", timer_offset_bug_warning, LITEST_SYNAPTICS_TOUCHPAD);
+	litest_add_for_device("timer:delay-warning", timer_delay_bug_warning, LITEST_MOUSE);
 	litest_add_no_device("timer:flush", timer_flush);
 
 	litest_add_no_device("misc:fd", fd_no_event_leak);