diff --git a/src/evdev.c b/src/evdev.c index 3f4e6aac..a5b1e2a9 100644 --- a/src/evdev.c +++ b/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); diff --git a/src/evdev.h b/src/evdev.h index 9a76ad80..8bc97be1 100644 --- a/src/evdev.h +++ b/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; diff --git a/src/libinput-private.h b/src/libinput-private.h index cb3a4017..72255ff8 100644 --- a/src/libinput-private.h +++ b/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; diff --git a/src/libinput.c b/src/libinput.c index e764375b..7a535986 100644 --- a/src/libinput.c +++ b/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; diff --git a/test/litest.c b/test/litest.c index 182094cb..91589c02 100644 --- a/test/litest.c +++ b/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) || - !strstr(format, "your system is too slow")) - litest_abort_msg("libinput bug triggered, aborting.\n"); + if ((RUNNING_ON_VALGRIND && in_debugger) || + !strstr(format, "scheduled expiry is in the past")) { + /* 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")) { diff --git a/test/test-misc.c b/test/test-misc.c index 901b6d4e..bf10ea83 100644 --- a/test/test-misc.c +++ b/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);