Delay ~1sec after each key press in insert mode on WSL2

[egorovpavel]

Summary

After update to 22.12, helix is no longer usable for editing files (within git repository). Every change or keypress takes about a second (many times over second). This most notable in insert mode, but also happens in normal mode when I change the content.

Hint: First noticed after this PR have been merged to master, so it somehow related to a git gutter implementation. However, the version compiled from this commit works. Also tested on mac and it works with no issues.

Reproduction Steps

I tried this:

In example below I hiting Enter 4 times in a row with no delay and then 4 times backspace.

I expected this to happen: see changes immediately as I type

Instead, this happened: see changes after delay

Helix log

~/.cache/helix/helix.log

2022-12-08T14:55:45.441 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/signatureHelp","params":{"position":{"character":0,"line":0},"textDocument":{"uri":"file:///home/user/hxbug/index.js"}},"id":1}
2022-12-08T14:55:45.445 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","id":1,"result":null}
2022-12-08T14:55:45.445 helix_lsp::transport [INFO] <- null
2022-12-08T14:55:45.445 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-12-08T14:55:46.032 helix_term::application [DEBUG] received editor event: IdleTimer
2022-12-08T14:55:46.032 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-12-08T14:55:46.181 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":0,"line":0},"start":{"character":0,"line":0}},"text":"\n"}],"textDocument":{"uri":"file:///home/user/hxbug/index.js","version":1}}}
2022-12-08T14:55:46.183 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"textDocument/publishDiagnostics","params":{"uri":"file:///home/user/hxbug/index.js","diagnostics":[]}}
2022-12-08T14:55:51.302 helix_vcs::diff::worker [INFO] Diff computation timed out, update of diffs might appear delayed
2022-12-08T14:55:51.302 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-12-08T14:55:51.302 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"textDocument/publishDiagnostics","params":{"uri":"file:///home/user/hxbug/index.js","diagnostics":[]}}
2022-12-08T14:55:51.302 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":0,"line":1},"start":{"character":0,"line":1}},"text":"\n"}],"textDocument":{"uri":"file:///home/user/hxbug/index.js","version":2}}}
2022-12-08T14:55:52.122 helix_vcs::diff::worker [INFO] Diff computation timed out, update of diffs might appear delayed
2022-12-08T14:55:52.122 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-12-08T14:55:52.123 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":0,"line":2},"start":{"character":0,"line":2}},"text":"\n"}],"textDocument":{"uri":"file:///home/user/hxbug/index.js","version":3}}}
2022-12-08T14:55:57.642 helix_vcs::diff::worker [INFO] Diff computation timed out, update of diffs might appear delayed
2022-12-08T14:55:57.642 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-12-08T14:55:57.643 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":0,"line":3},"start":{"character":0,"line":3}},"text":"\n"}],"textDocument":{"uri":"file:///home/user/hxbug/index.js","version":4}}}
2022-12-08T14:55:57.645 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"textDocument/publishDiagnostics","params":{"uri":"file:///home/user/hxbug/index.js","diagnostics":[]}}
2022-12-08T14:56:00.122 helix_vcs::diff::worker [INFO] Diff computation timed out, update of diffs might appear delayed
2022-12-08T14:56:00.123 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-12-08T14:56:00.124 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":0,"line":4},"start":{"character":0,"line":3}},"text":""}],"textDocument":{"uri":"file:///home/user/hxbug/index.js","version":5}}}
2022-12-08T14:56:00.153 helix_vcs::diff::worker [INFO] Diff computation timed out, update of diffs might appear delayed
2022-12-08T14:56:00.153 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-12-08T14:56:00.154 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":0,"line":3},"start":{"character":0,"line":2}},"text":""}],"textDocument":{"uri":"file:///home/user/hxbug/index.js","version":6}}}
2022-12-08T14:56:04.123 helix_vcs::diff::worker [INFO] Diff computation timed out, update of diffs might appear delayed
2022-12-08T14:56:04.123 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-12-08T14:56:04.123 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":0,"line":2},"start":{"character":0,"line":1}},"text":""}],"textDocument":{"uri":"file:///home/user/hxbug/index.js","version":7}}}
2022-12-08T14:56:05.053 helix_vcs::diff::worker [INFO] Diff computation timed out, update of diffs might appear delayed
2022-12-08T14:56:05.053 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-12-08T14:56:05.053 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"contentChanges":[{"range":{"end":{"character":0,"line":1},"start":{"character":0,"line":0}},"text":""}],"textDocument":{"uri":"file:///home/user/hxbug/index.js","version":8}}}
2022-12-08T14:56:10.154 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"textDocument/publishDiagnostics","params":{"uri":"file:///home/user/hxbug/index.js","diagnostics":[]}}
2022-12-08T14:56:10.154 helix_vcs::diff::worker [INFO] Diff computation timed out, update of diffs might appear delayed
2022-12-08T14:56:10.154 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0
2022-12-08T14:56:10.155 helix_term::application [DEBUG] received editor event: LanguageServerMessage((0, Notification(Notification { jsonrpc: Some(V2), method: "textDocument/publishDiagnostics", params: Map({"diagnostics": Array [], "uri": String("file:///home/user/hxbug/index.js")}) })))
2022-12-08T14:56:10.155 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/signatureHelp","params":{"position":{"character":0,"line":3},"textDocument":{"uri":"file:///home/user/hxbug/index.js"}},"id":2}
-12-08T14:56:10.155 helix_view::document [DEBUG] id 2 modified - last saved: 0, current: 0

Platform

WSL2 / Ubuntu 20.04 LTS / Windows 10

Terminal Emulator

wezterm 20221119-145034-49b9839f, Windows-Terminal Version: 1.15.2874.0

Helix Version

helix 22.12 (96ff64a)

[CptPotato]

Does this only happen using WSL or also when you run helix natively on Windows?

I'm not very familiar with helix' git implementation, but I know that Windows can be excessively slow when reading/writing many files, especially when third party antivirus software is used. So slowness due to file i/o could be a culprit. Edit: likely not the issue, as mentioned below.

[pascalkuthe]

@CptPotato Helix does not perform IO on every keypress. Instead only once when a file is loaded or when:reload is used so I doubt that IO problems are the issue here. The previous commit that OP pointed to that was working was a version of diff gutter that runs fully async. The current version blocks the rendering until a the git diff is finished (asynvhrousnly) or a 12ms timeout expires (if the diff timeout is reached, it updates asynchronously and redraws later) with some locking tricks. Since that version does not additional IO I doubt that is related. I would rather guess that locks or timers somehow missbehave/behave differently then considered on WSL2.

I would suspect that either locks or timers misbehave on wsl2 somehow or behave different in a way I had not considered. This will likely be challenging to debug. @egorovpavel it would help point us in the right direction if you could tell us whether this bug also occurs on windows natively

[egorovpavel]

@pascalkuthe on windows 10 it works with no issues as well. Will try to install and test on fresh WSL instance to isolate better from stuff installed on my current working WSL instance.

[egorovpavel]

@pascalkuthe on fresh WSL instance with ubuntu I have the same issue as described above. Let me know if there is anything I can try to debug this issue?

[pascalkuthe]

Thanks for performing those tests. Sadly I can't debug this myself as I can't run WSL2 inside a windows VM easily (that would be nested virtualization) and I don't have windows installed anywhere. Therefore I am going to need some help with debugging this.

I created a fork which contains a bunch of extra logging: https://github.com/pascalkuthe/helix/tree/git_gutter_test
Please clone that branch somewhere and try compiling/running it on WSL with the following command cargo run --release -- -v --log test.log. Afterwards please post the test.log file as a gist here.

[egorovpavel]

@pascalkuthe here are the results(I entered into insert mode then typed asdf end exited to normal mode):

2022-12-12T21:28:37.478 helix_view::editor [ERROR] Failed to initialize the LSP for `source.md` { cannot find binary path }
2022-12-12T21:28:43.599 helix_vcs::diff [INFO] aquire renderlock and wait
2022-12-12T21:28:43.600 helix_vcs::diff::worker [INFO] start event accumulation
2022-12-12T21:29:05.391 helix_vcs::diff::worker [INFO] finished event accumulation
2022-12-12T21:29:05.391 helix_vcs::diff::worker [INFO] start diff
2022-12-12T21:29:05.391 helix_vcs::diff::worker [INFO] finish diff
2022-12-12T21:29:05.391 helix_vcs::diff::worker [INFO] start polling timeout
2022-12-12T21:29:05.391 helix_vcs::diff::worker [INFO] Dropping render lock
2022-12-12T21:29:05.391 helix_vcs::diff::worker [INFO] Diff computation timed out, update of diffs might appear delayed
2022-12-12T21:29:05.393 helix_vcs::diff [INFO] aquire renderlock and wait
2022-12-12T21:29:05.393 helix_vcs::diff::worker [INFO] start event accumulation
2022-12-12T21:29:32.762 helix_vcs::diff::worker [INFO] finished event accumulation
2022-12-12T21:29:32.763 helix_vcs::diff::worker [INFO] start diff
2022-12-12T21:29:32.763 helix_vcs::diff::worker [INFO] finish diff
2022-12-12T21:29:32.763 helix_vcs::diff::worker [INFO] start polling timeout
2022-12-12T21:29:32.763 helix_vcs::diff::worker [INFO] Dropping render lock
2022-12-12T21:29:32.763 helix_vcs::diff::worker [INFO] Diff computation timed out, update of diffs might appear delayed
2022-12-12T21:29:32.764 helix_vcs::diff [INFO] aquire renderlock and wait
2022-12-12T21:29:32.764 helix_vcs::diff::worker [INFO] start event accumulation
2022-12-12T21:29:43.643 helix_vcs::diff::worker [INFO] finished event accumulation
2022-12-12T21:29:43.643 helix_vcs::diff::worker [INFO] start diff
2022-12-12T21:29:43.643 helix_vcs::diff::worker [INFO] finish diff
2022-12-12T21:29:43.643 helix_vcs::diff::worker [INFO] start polling timeout
2022-12-12T21:29:43.644 helix_vcs::diff::worker [INFO] Dropping render lock
2022-12-12T21:29:43.644 helix_vcs::diff::worker [INFO] Diff computation timed out, update of diffs might appear delayed
2022-12-12T21:29:43.645 helix_vcs::diff [INFO] aquire renderlock and wait
2022-12-12T21:29:43.646 helix_vcs::diff::worker [INFO] start event accumulation
2022-12-12T21:30:00.124 helix_vcs::diff::worker [INFO] finished event accumulation
2022-12-12T21:30:00.124 helix_vcs::diff::worker [INFO] start diff
2022-12-12T21:30:00.124 helix_vcs::diff::worker [INFO] finish diff
2022-12-12T21:30:00.124 helix_vcs::diff::worker [INFO] start polling timeout
2022-12-12T21:30:00.124 helix_vcs::diff::worker [INFO] Dropping render lock
2022-12-12T21:30:00.124 helix_vcs::diff::worker [INFO] Diff computation timed out, update of diffs might appear delayed

[pascalkuthe]

Thanks for reporting back on this 🙏 This issue is really difficult for me to debug.

From these logs it actually looks like you are waiting more like 10-20s :O
The strangest part is that it basically seems to take forever to accumulate events which should be capped to 1ns per debounced event (and nothing performance intensive is happening there) that is very odd. I am guessing that somehow tokio doesn't wake-up the task on the 1ns timeout. I originally assumed some kind problem that the tokio runtime might have with helix when very few threads are available but even with a single worker thread I am not able to reproduce this at all....

I really didn't suspect a problem in this part so I only added some sparse logging there. I push a new commit that adds a bunch more logs here basically anytime someting happens. It would be nice if you could test again @egorovpavel so I could be sure this is really the timeout or if I missed something else

[egorovpavel]

@pascalkuthe this is super weird... but after running wsl --shutdown its no longer an issue . The strange thing that It was reproduced before in a fresh instance of WSL that was created from different ubuntu distro (my current 20.04 and a new one was 21.04). Looks like there is bug in WSL that accumulated overtime and shared across running instances...

Anyway thank you and sorry for wasting your time.