Bug 206929 - Input Regression >= 5.4: The event timestamp of key release is wrong.
Summary: Input Regression >= 5.4: The event timestamp of key release is wrong.
Status: RESOLVED CODE_FIX
Alias: None
Product: Drivers
Classification: Unclassified
Component: Input Devices (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: Dmitry Torokhov
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2020-03-23 12:20 UTC by teika kazura
Modified: 2020-04-02 04:46 UTC (History)
1 user (show)

See Also:
Kernel Version: >= 5.4
Subsystem:
Regression: No
Bisected commit-id:

Attachments
evtest result. (32.26 KB, text/plain)
2020-03-25 06:41 UTC, teika kazura 		Details
Fix stale timestamp on autorepeat events (930 bytes, patch)
2020-03-25 18:07 UTC, Dmitry Torokhov 		Details | Diff
Add an attachment (proposed patch, testcase, etc.)

Description teika kazura 2020-03-23 12:20:15 UTC 
Input Regression >= 5.4: The event timestamp of key release is wrong.

After the commit 3b51c44bd6936e8 (between 5.3 and 5.4), the timestamp of a key release event is that of the preceding key press event. Reverting this commit fixes the problem.

This timestamp can be obtained as:
  struct input_event ev;
  ev->time;

(If want a debug code, I will send a code to show timestamps in Xorg.0.log - I discovered this by my fork of xf86-input-evdev driver. Though I don't think it's difficult to monitor them.)

Note: A commit in Aug 2019 (4370b231d1001e0b560f82) fixes one bug of 3b51c44, but that's irrelevant to this report.

Thatks a lot. Best regards.

The above mentioned commit can be found here:
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit?id=3b51c44bd6936e86a7180abd9aebc4387a479253
------------------------------------------------------------------------
author    Atif Niyaz <atifniyaz@google.com>	2019-07-24 22:26:31 +0300
committer Dmitry Torokhov <dmitry.torokhov@gmail.com>	2019-07-25 11:12:20 +0300

Input: allow drivers specify timestamp for input events
Currently, evdev stamps events with timestamps acquired in evdev_events()
However, this timestamping may not be accurate in terms of measuring
when the actual event happened.

Let's allow individual drivers specify timestamp in order to provide a more
accurate sense of time for the event. It is expected that drivers will set the
timestamp in their hard interrupt routine.
------------------------------------------------------------------------
Comment 1 Dmitry Torokhov 2020-03-24 02:03:57 UTC 
What driver do you observe this with?
Comment 2 teika kazura 2020-03-24 04:10:16 UTC 
It's with USB keyboard, but *not* with AT Translated. (Sorry, I noticed it just now, but I should have reported it my first post.)

The story below is about my hack of xf86-input-evdev[1]. I'm not sure if you're interested, but rather than omitting, I include it here.

My hack enables e.g. "Space/Shift dual role key"(s); if you press the space key alone, it's the space. But if you press it with other keys, it works as the shift key. (Or any combination is possible.)

My hack measures timestmaps in the following reason: It allows "hesitate, change your mind, and cancel" - You often press the Space key, intending Shift, but after a while, you release it without pressing other keys. In such cases, it's convenient not to dispatch the Space press/release events, in another words, not to send any events. The criterion here is how long the press lasts.

Thanks Dmitry for your work in the kernel input driver.

[1]
You can get it
* For ArchLinux: https://bbs.archlinux.org/viewtopic.php?id=119556
* For Gentoo: https://forums.gentoo.org/viewtopic-t-865313.html
* Website: https://gitlab.com/at-home-modifier/at-home-modifier-evdev/-/wikis/home
Comment 3 Dmitry Torokhov 2020-03-24 17:48:39 UTC 
Does your USB keyboard work with hid-generic driver or you are using some other driver? Here is what I see on my system with USB keyboard and hid-generic:

Event: time 1585071556.237691, type 4 (EV_MSC), code 4 (MSC_SCAN), value 70007
Event: time 1585071556.237691, type 1 (EV_KEY), code 32 (KEY_D), value 1
Event: time 1585071556.237691, -------------- SYN_REPORT ------------
dEvent: time 1585071556.365697, type 4 (EV_MSC), code 4 (MSC_SCAN), value 70007
Event: time 1585071556.365697, type 1 (EV_KEY), code 32 (KEY_D), value 0
Event: time 1585071556.365697, -------------- SYN_REPORT ------------
Event: time 1585071558.109817, type 4 (EV_MSC), code 4 (MSC_SCAN), value 70009
Event: time 1585071558.109817, type 1 (EV_KEY), code 33 (KEY_F), value 1
Event: time 1585071558.109817, -------------- SYN_REPORT ------------
fEvent: time 1585071558.213694, type 4 (EV_MSC), code 4 (MSC_SCAN), value 70009
Event: time 1585071558.213694, type 1 (EV_KEY), code 33 (KEY_F), value 0
Event: time 1585071558.213694, -------------- SYN_REPORT ------------
Event: time 1585071559.549715, type 4 (EV_MSC), code 4 (MSC_SCAN), value 7000a
Event: time 1585071559.549715, type 1 (EV_KEY), code 34 (KEY_G), value 1
Event: time 1585071559.549715, -------------- SYN_REPORT ------------
gEvent: time 1585071559.629689, type 4 (EV_MSC), code 4 (MSC_SCAN), value 7000a
Event: time 1585071559.629689, type 1 (EV_KEY), code 34 (KEY_G), value 0
Event: time 1585071559.629689, -------------- SYN_REPORT ------------

As you can see, the event time(s) for EV_KEY/KEY_XXX are all different.

Can you please show me the sequence on your system (using evtest)?
Comment 4 teika kazura 2020-03-25 06:41:04 UTC 
Created attachment 288041 [details]
evtest result.

hid-generic, according to dmesg:
------------------------------------------------------------------------
usb 1-2: New USB device found, idVendor=0566, idProduct=3029, bcdDevice= 1.01
usb 1-2: New USB device strings: Mfr=0, Product=0, SerialNumber=0
input: HID 0566:3029 as /devices/pci0000:00/0000:00:14.0/usb1/1-2/1-2:1.0/0003:0566:3029.0001/input/input7
hid-generic 0003:0566:3029.0001: input,hidraw0: USB HID v1.11 Keyboard [HID 0566:3029] on usb-0000:00:14.0-2/input0
------------------------------------------------------------------------

hwinfo says usbhid:
------------------------------------------------------------------------
37: USB 00.0: 10800 Keyboard
  [Created at usb.122]
  Unique ID: cLrx.ZeV332yiCcA
  Parent ID: k4bc.2DFUsyrieMD
  SysFS ID: /devices/pci0000:00/0000:00:14.0/usb1/1-2/1-2:1.0
  SysFS BusID: 1-2:1.0
  Hardware Class: keyboard
  Model: "Monterey International Keyboard"
  Hotplug: USB
  Vendor: usb 0x0566 "Monterey International Corp."
  Device: usb 0x3029
  Revision: "1.01"
  Driver: "usbhid"
  Driver Modules: "usbhid"
------------------------------------------------------------------------
But my evtest result confirms my report. See the attachment. (Same from VT1, but it must be independent from Xorg.)

At least one another user experiences this issue[1]. If you want, I can ask that person to send an evtest result, or other info.

[1] https://bbs.archlinux.org/viewtopic.php?pid=1890663#p1890663 (comment #55, by "Salkay")

Thanks.
Comment 5 Dmitry Torokhov 2020-03-25 16:50:47 UTC 
OK, I see. It looks like we do not reset the timestamp for autorepeat events synthesized by the kernel.
Comment 6 Dmitry Torokhov 2020-03-25 18:07:14 UTC 
Created attachment 288053 [details]
Fix stale timestamp on autorepeat events

Please let me know if this patch works for you and if it does if you are happy with the info in "reported-by" tag in the patch.
Comment 7 teika kazura 2020-03-26 12:53:43 UTC 
Gorspugee, it worked against 5.5.12! I'm ok with the reported-by tag. I am happy if my report was of any help.

I appreciate not only your technical help, but also your kind replies. Thank you very much.
...или пожалуй большое спасибо, Дмитрий Великиевич. (Sorry if this line doesn't make sense.)

Best regards.
Comment 8 Dmitry Torokhov 2020-03-27 02:33:56 UTC 
Great, thank you for reporting and testing. I just send a pull request so the fix should land in 5.6 and then propagate to stable releases.
Note You need to log in before you can comment on or make changes to this bug.