nog
nog copied to clipboard
TimUntersberger
The new keyboard hook lets keypresses go through
Version (which release did you use?) The latest git version
Describe the bug
The new keyboard hook functionality does not always work correctly, and some of the keypresses gets sent to the application in additon to Nog handling it. In fact for me this is so common that it's almost unusable at the moment.
To Reproduce
The easiest way to produce it is probably to have a workspace with text editors open, and switch the focus between them. But I'm not sure if it's reproducable on all systems.
Expected behavior
All handled keypresses should be swallowed.
More details
I think I know what's going on, since I debugged this a bit. When a key is pressed, a message is sent to another thread through a channel, and once it's handled there, another message is sent back indicate that the key was handled. The main hook thread waits for 100ms to get this message back, and if it doesn't it lets the key press through to other applications. So that's one press getting through even if it's not handled. But what's worse is that the channel is now out of sync (there's more than one message in the queue), so it will start to block KeyUp events instead of KeyDown, which makes things worse.
This 100ms is warranted, as Windows requires the keyboard hooks to not take too long, so that can't be changed. One way to mitigate the issue would be to use a higher thread priority for the processing thread, but that's still quite fragile, it's quite hard to guarantee these timing requirements in all cases.
So instead I recommend, that the actual keymappig is checked inside the hook function, to avoid having to rely on context switches being fast enough. Another improvement for that would be to make sure that no thread locking happens there, for example by making the keymappings buffered so that atomic swaps are used to bring in the new mappings.
This still has a small problem that I don't know how to solve easily, if the mapping is changed by a mode switch, and a new keypress happens immediately after, the re-mapping might not be processed fast enough. But that's probably a very small problem. I can think of a couple of wayst to solve it, but neither of them is easy or desirable.
One way is to have a completely static mapping, that is the mapping of all modes and the mode switches are know in advance. Then the switching would be easily done quickly in the hook itself.
Another way would be to somehow be able to call lua in a way that only allows remapping calls, which probably also would be quick enough.
A third way, very similar to the second one is to queue all real actions, like focusing windows, switching workspaces and so on, but still call lua for every keypress. Lua is quite fast by itself so I think it should be fast enough, and if not, luajit would definitely be able to do it. So that would IMO be the eventual real fix for the issue. This way the lua script could probably be called from the hook function itself on every keypress. And then there's a separate processor that makes all the magic happen.
Note that the issue is probably much worse than it should be right now, at the moment Nog seems to use 100% cpu of one core at all times, which probably delays some actions for more than 100ms. I haven't tracked down what's causing that.
Also note that it would probably be worth blocking key up events as well. They could be done by for example storing handled keys (without modifiers), in a HashSet, and then check that and remove the key on key up.
Actually the problem seems to be mostly related to mode changes, at least that's how I can most easily reproduce. So it seems the remapping is quite slow. But it probably also happens when doing more complex window manipulation, so I don't think it's restricted to that.
I was actually hoping that the keyboard hooks would solve the slow remapping, as I could not use the modes like I wanted to before either, it was simply to slow to re-map, so following keys got ignored. With the support of the QMK firmware for the keyboard, my goal is to use just a single stolen hotkey, which then enables different modes on following keypresses, and automatically sends esc to exit the modes when I release that key. The chords feature request might also be applicable for that behaviour, but using manual modes would be even more flexible, for example I could keep holding down my trigger key, while pressing multiple navigation keys.
The main hook thread waits for 100ms to get this message back, and if it doesn't it lets the key press through to other applications
My first idea would be to see why the check even takes more than 100ms.
If you wrap everything inside this while loop with our time! macro like this:
time!("kb event loop", { ... })
you can see how long each iteration in the event loop takes. Mine take 5 - 10 µs
I didn't add the timing but I have a log with reasonable timestamps and output to see the problem.
It actually goes out of sync at the very start, when entering work mode. It is possible that some of my display changes makes that part slower.
[2021-08-05 16:39:29.347223 +03:00] INFO [twm\src\main.rs:1031] Listening for keybindings
[2021-08-05 16:39:32.500297 +03:00] INFO [twm\src\keyboardhook.rs:163] KeyDown 87
[2021-08-05 16:39:32.500348 +03:00] INFO [twm\src\keybindings.rs:54] Input event key down 87
[2021-08-05 16:39:32.500435 +03:00] INFO [twm\src\keybindings.rs:76] sending true
[2021-08-05 16:39:32.500484 +03:00] INFO [twm\src\keyboardhook.rs:195] Processed key 87
[2021-08-05 16:39:32.500463 +03:00] DEBUG [twm\src\main.rs:1071] Received keybinding Keybinding(CONTROL+LALT+W, 13, Global, 9087, None)
[2021-08-05 16:39:32.501507 +03:00] INFO [twm\src\bar\create.rs:125] Creating appbar
[2021-08-05 16:39:32.501606 +03:00] DEBUG [twm\src\bar\create.rs:152] Creating appbar for display DisplayId(65539)
[2021-08-05 16:39:32.508433 +03:00] DEBUG [twm\src\bar\create.rs:152] Creating appbar for display DisplayId(65537)
[2021-08-05 16:39:32.521372 +03:00] DEBUG [twm\src\bar\create.rs:152] Creating appbar for display DisplayId(10628619)
[2021-08-05 16:39:32.532365 +03:00] INFO [twm\src\tile_grid\store.rs:22] Saving 1 c0|60[t0|60|200230,r1|60[t0|60|329888,t1|60|789124]]
[2021-08-05 16:39:32.568499 +03:00] INFO [twm\src\tile_grid\store.rs:22] Saving 2 t0|120|134196
[2021-08-05 16:39:32.569223 +03:00] DEBUG [twm\src\system\win.rs:458] Rule(chrome.exe) matched!
[2021-08-05 16:39:32.569812 +03:00] INFO [twm\src\tile_grid\store.rs:22] Saving 3 c0|120[t0|60|722200,t1|60|2235598]
[2021-08-05 16:39:32.572065 +03:00] INFO [twm\src\tile_grid\store.rs:22] Saving 4 t0|120|10754592
[2021-08-05 16:39:32.573394 +03:00] INFO [twm\src\tile_grid\store.rs:22] Saving 5 t0|120|5245030
[2021-08-05 16:39:32.574494 +03:00] INFO [twm\src\tile_grid\store.rs:22] Saving 6 t0|120|134164
[2021-08-05 16:39:32.575254 +03:00] DEBUG [twm\src\system\win.rs:458] Rule(chrome.exe) matched!
[2021-08-05 16:39:32.575937 +03:00] INFO [twm\src\tile_grid\store.rs:22] Saving 7 t0|120|134170
[2021-08-05 16:39:32.576795 +03:00] DEBUG [twm\src\system\win.rs:458] Rule(chrome.exe) matched!
[2021-08-05 16:39:32.577061 +03:00] INFO [twm\src\tile_grid\store.rs:22] Saving 8
[2021-08-05 16:39:32.577498 +03:00] INFO [twm\src\tile_grid\store.rs:22] Saving 9
[2021-08-05 16:39:32.578386 +03:00] INFO [twm\src\tile_grid\store.rs:22] Saving 10
[2021-08-05 16:39:32.579219 +03:00] DEBUG [twm\src\tile_grid.rs:48] IsFullScreened? false FocusedNode: Some(4)
[2021-08-05 16:39:32.579733 +03:00] DEBUG [twm\src\tile_grid.rs:54]
████████████████████████████████████████████████████████████████
█AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA██BBBBBBBBBBBBBBBBBBBBBBBBBBBBBB█
█AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA██BBBBBBBBBBBBBBBBBBBBBBBBBBBBBB█
█AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA██BBBBBBBBBBBBBBBBBBBBBBBBBBBBBB█
█AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA██BBBBBBBBBBBBBBBBBBBBBBBBBBBBBB█
█AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA██BBBBBBBBBBBBBBBBBBBBBBBBBBBBBB█
█AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA██BBBBBBBBBBBBBBBBBBBBBBBBBBBBBB█
█AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA██BBBBBBBBBBBBBBBBBBBBBBBBBBBBBB█
█AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA██BBBBBBBBBBBBBBBBBBBBBBBBBBBBBB█
█AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA█████████████████████████████████
█AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA█████████████████████████████████
█AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA██CCCCCCCCCCCCCCCCCCCCCCCCCCCCCC█
█AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA██CCCCCCCCCCCCCCCCCCCCCCCCCCCCCC█
█AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA██CCCCCCCCCCCCCCCCCCCCCCCCCCCCCC█
█AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA██CCCCCCCCCCCCCCCCCCCCCCCCCCCCCC█
█AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA██CCCCCCCCCCCCCCCCCCCCCCCCCCCCCC█
█AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA██CCCCCCCCCCCCCCCCCCCCCCCCCCCCCC█
█AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA██CCCCCCCCCCCCCCCCCCCCCCCCCCCCCC█
█AAAAAAAAAAAAAAAAAAAAAAAAAAAAAA██CCCCCCCCCCCCCCCCCCCCCCCCCCCCCC█
████████████████████████████████████████████████████████████████
A ~ NodeID:1 WinID:200230 - keybindings.rs (/mnt/c/proj/nog/twm/src) - NVIM Size: 60 Order: 0
B ~ NodeID:3 WinID:329888 - C:\WINDOWS\System32\WindowsPowerShell\v1.0\powershell.exe Size: 60 Order: 0
C ~ NodeID:4 WinID:789124 - C:\WINDOWS\SYSTEM32\wsl.exe Size: 60 Order: 1
[2021-08-05 16:39:32.580016 +03:00] INFO [twm\src\tile_grid.rs:78] Beginning Rendering
[2021-08-05 16:39:32.587066 +03:00] INFO [twm\src\tile_grid.rs:109] Rendering completed
[2021-08-05 16:39:32.633359 +03:00] INFO [twm\src\keyboardhook.rs:163] KeyDown 0
[2021-08-05 16:39:32.833763 +03:00] INFO [twm\src\keyboardhook.rs:201] Timeout 0
[2021-08-05 16:39:32.834141 +03:00] INFO [twm\src\keyboardhook.rs:186] KeyUp 87
[2021-08-05 16:39:33.039685 +03:00] INFO [twm\src\keyboardhook.rs:201] Timeout 87
[2021-08-05 16:39:33.045113 +03:00] DEBUG [twm\src\main.rs:827] Sending redraw-app-bar event
[2021-08-05 16:39:33.045243 +03:00] INFO [twm\src\main.rs:564] Registering windows event handler
[2021-08-05 16:39:33.045372 +03:00] INFO [twm\src\keybindings.rs:54] Input event key down 0
[2021-08-05 16:39:33.045402 +03:00] INFO [twm\src\keybindings.rs:87] sending false
[2021-08-05 16:39:33.045440 +03:00] INFO [twm\src\keybindings.rs:82] Input event key up 87
[2021-08-05 16:39:33.045454 +03:00] INFO [twm\src\keybindings.rs:87] sending false
[2021-08-05 16:39:33.045422 +03:00] DEBUG [twm\src\system\win\win_event_listener.rs:83] Registering win event hook
[2021-08-05 16:39:33.101903 +03:00] DEBUG [twm\src\event_handler\winevent.rs:36] FocusChange: 'alacritty.exe' | 789124
[2021-08-05 16:39:33.245301 +03:00] DEBUG [twm\src\event_handler\winevent.rs:36] FocusChange: 'alacritty.exe' | 329888
[2021-08-05 16:39:36.356771 +03:00] INFO [twm\src\keyboardhook.rs:163] KeyDown 87
[2021-08-05 16:39:36.356787 +03:00] INFO [twm\src\keybindings.rs:54] Input event key down 87
[2021-08-05 16:39:36.356825 +03:00] INFO [twm\src\keyboardhook.rs:198] Did not process key 87
[2021-08-05 16:39:36.356840 +03:00] INFO [twm\src\keybindings.rs:76] sending true
[2021-08-05 16:39:36.356876 +03:00] DEBUG [twm\src\main.rs:1071] Received keybinding Keybinding(CONTROL+WIN+W, 51, Normal, 3087, None)
[2021-08-05 16:39:36.364340 +03:00] INFO [twm\src\keybindings.rs:82] Input event key up 87
[2021-08-05 16:39:36.364331 +03:00] INFO [twm\src\keyboardhook.rs:186] KeyUp 87
[2021-08-05 16:39:36.364385 +03:00] INFO [twm\src\keybindings.rs:87] sending false
[2021-08-05 16:39:36.364407 +03:00] INFO [twm\src\keyboardhook.rs:198] Did not process key 87
[2021-08-05 16:39:36.532291 +03:00] INFO [twm\src\keyboardhook.rs:163] KeyDown 76
[2021-08-05 16:39:36.532328 +03:00] INFO [twm\src\keyboardhook.rs:195] Processed key 76
[2021-08-05 16:39:36.532338 +03:00] INFO [twm\src\keybindings.rs:54] Input event key down 76
[2021-08-05 16:39:36.532362 +03:00] INFO [twm\src\keybindings.rs:76] sending true
[2021-08-05 16:39:36.532386 +03:00] DEBUG [twm\src\main.rs:1071] Received keybinding Keybinding(L, 54, Normal, 76, None)
[2021-08-05 16:39:36.532473 +03:00] INFO [twm\src\keyboardhook.rs:163] KeyDown 0
[2021-08-05 16:39:36.532485 +03:00] INFO [twm\src\keyboardhook.rs:198] Did not process key 0
The first two key ups (the w for the workmode, and the dummy key for the focusing) times out badly.
For example the event received by the hook at 16:39:32.633359, is processed at 16:39:33.045372, between that is
[2021-08-05 16:39:33.045113 +03:00] DEBUG [twm\src\main.rs:827] Sending redraw-app-bar event
[2021-08-05 16:39:33.045243 +03:00] INFO [twm\src\main.rs:564] Registering windows event handler
So my bet is that either of those blocks for too long.
Note that I currently have a timeout set to 200ms, so that's why you see around that time until I print the timeout message. Also note that the channel is at the wrong state at that point, so it's hard to tell if something else takes too long. But yes generally at least the timing between the KeyDown or KeyUp in the hook and the sending to the channel in the Keybindings.rs seems to be ok.
I added some quick timings to the enter_work_mode function, and there are several things that takes a long time. But the change workspace is the biggest culprit, and since it holds the lock it makes the key processing timeout.
I don't have time to look at it further, but there might also be some semi deadlocking going on. Since when I increase the TIME_DURATION, changing workspaces takes longer. For example when I had it at 900 ms, it took over 1s, while now when I have it at 100, it took around 350 ms. But it could also just be statistical noise.
I was supposed to do other things, but I could not stop myself, since at least a temporary solution came to my mind.
It's clear that it was the state_arc locking inside keybindings.rs:listen that was the problem. And that lock is not really needed, the solution was simple, just send the whole keybindings array over the channel.
But there was still a problem after that, the UpdateKeybindings event can be sent without keypresses, so they can queue up a bit, which made the keybindings not update until you had pressed a certain amount of time. So I just used a loop instead of if, and it seems to be working now.
I will run with this for a while now and see if it's really fixed, and if it is, send a pull request at some point.