Rust-analyzer: Pressing enter only results in inserting a newline after more than half a minute
After installing the latest version of rust analyzer, I noticed that pressing Enter (either the default or numpad Enter) doesn't result in a newline. After a seemingly arbitrary delay of over 30 seconds, a new line is inserted after all.
I also tried copying and pasting a newline, which works without any trouble.
It seems like it is a regression from my previous install (last week). Currently I am on commit 91bd783273477d.
Wodann
All 32 comments
Assuming vscode, is there anything showing in the output / traces?
Was it a normal project and/or something similar to the case in https://github.com/rust-analyzer/rust-analyzer/issues/1259?
memoryruins
on 26 May 2019
I sometimes get this. A temporary workaround of using ctrl+enter rather than just ctrl has worked for me.
DJMcNab
on 26 May 2019
@memoryruins Yes, it is vscode. Sorry for not mentioning that.
I had a look at issue #1259. I am not sure whether there is any difference between his project or mine. I have a workspace crate that contains four crates, which are used as dependencies amongst each other (very similar to RA's structure)
The reported error seems different from #1259 though. From what I could determine from the log, it consistently takes about 15 seconds for the server to respond to a request. Sometimes the server reports that the client cancelled a request. The reception of a response doesn't directly result in the addition of a newline. Eventually all enters are processed and cause newlines to occur at the original location of execution.
Some additional observations:
- Before the
Start watching changes with cargo?pops up, I can briefly press enter. - It does seem like RA is capable of "recovering" from this issue as after leaving RA unmanaged for some time it can randomly happen that enters start and keep responding directly.
This is just me hypothesizing, but it almost seems like some work is happening in the background that stalls requests. As requests start racking up, this causes further delays. When left for a while, the queue slowly empties. After this further requests can happen directly again.
Could it maybe be caused by the initial loading of modules, as that might take some time. It's weird that I can type other symbols than Enter without any issues though.
@DJMcNab Thank you! Pressing Ctrl + Enter actually works :)
The trace reports the following:
EDIT(@matklad): hide the trace under <details>
[Trace - 18:23:04] Sending request 'rust-analyzer/onEnter - (38)'.
Params: {
"textDocument": {
"uri": "file:///e%3A/dev/src/se4_core/crates/se4_db/src/lib.rs"
},
"position": {
"line": 26,
"character": 5
}
}
[Trace - 18:23:16] Received response 'textDocument/codeAction - (29)' in 13268ms. Request failed: canceled by client (-32800).
[Trace - 18:23:16] Received response 'textDocument/foldingRange - (24)' in 14608ms. Request failed: canceled by client (-32800).
[Trace - 18:23:16] Received response 'textDocument/codeAction - (30)' in 12909ms. Request failed: canceled by client (-32800).
[Trace - 18:23:18] Received response 'textDocument/documentSymbol - (28)' in 16663ms.
Result: [
{
"deprecated": false,
"kind": 2,
"name": "tests",
"range": {
"end": {
"character": 12,
"line": 41
},
"start": {
"character": 0,
"line": 40
}
},
"selectionRange": {
"end": {
"character": 9,
"line": 41
},
"start": {
"character": 4,
"line": 41
}
}
},
{
"children": [
{
"deprecated": false,
"detail": "fn(&self, name: &str, user: &str, pwd: &str) -> DbResult<DbClient>",
"kind": 12,
"name": "auth_db",
"range": {
"end": {
"character": 5,
"line": 37
},
"start": {
"character": 4,
"line": 31
}
},
"selectionRange": {
"end": {
"character": 18,
"line": 31
},
"start": {
"character": 11,
"line": 31
}
}
},
{
"deprecated": false,
"detail": "fn(address: &str, port: u16, options: Option<ClientOptions>) -> DbResult<DbServer>",
"kind": 12,
"name": "connect",
"range": {
"end": {
"character": 5,
"line": 26
},
"start": {
"character": 4,
"line": 19
}
},
"selectionRange": {
"end": {
"character": 18,
"line": 19
},
"start": {
"character": 11,
"line": 19
}
}
}
],
"deprecated": false,
"kind": 19,
"name": "impl DbServer",
"range": {
"end": {
"character": 1,
"line": 38
},
"start": {
"character": 0,
"line": 18
}
},
"selectionRange": {
"end": {
"character": 13,
"line": 18
},
"start": {
"character": 5,
"line": 18
}
}
},
{
"children": [
{
"deprecated": false,
"detail": "gridfs::Store",
"kind": 8,
"name": "fs",
"range": {
"end": {
"character": 25,
"line": 15
},
"start": {
"character": 4,
"line": 15
}
},
"selectionRange": {
"end": {
"character": 10,
"line": 15
},
"start": {
"character": 8,
"line": 15
}
}
},
{
"deprecated": false,
"detail": "mongodb::db::Database",
"kind": 8,
"name": "db",
"range": {
"end": {
"character": 33,
"line": 14
},
"start": {
"character": 4,
"line": 14
}
},
"selectionRange": {
"end": {
"character": 10,
"line": 14
},
"start": {
"character": 8,
"line": 14
}
}
}
],
"deprecated": false,
"kind": 23,
"name": "DbClient",
"range": {
"end": {
"character": 1,
"line": 16
},
"start": {
"character": 0,
"line": 13
}
},
"selectionRange": {
"end": {
"character": 19,
"line": 13
},
"start": {
"character": 11,
"line": 13
}
}
},
{
"children": [
{
"deprecated": false,
"detail": "Client",
"kind": 8,
"name": "client",
"range": {
"end": {
"character": 18,
"line": 10
},
"start": {
"character": 4,
"line": 10
}
},
"selectionRange": {
"end": {
"character": 10,
"line": 10
},
"start": {
"character": 4,
"line": 10
}
}
}
],
"deprecated": false,
"kind": 23,
"name": "DbServer",
"range": {
"end": {
"character": 1,
"line": 11
},
"start": {
"character": 0,
"line": 9
}
},
"selectionRange": {
"end": {
"character": 19,
"line": 9
},
"start": {
"character": 11,
"line": 9
}
}
}
]
[Trace - 18:23:18] Received response 'textDocument/codeLens - (27)' in 16760ms.
Result: [
{
"data": {
"impls": {
"position": {
"character": 0,
"line": 9
},
"textDocument": {
"uri": "file:///e%3A/dev/src/se4_core/crates/se4_db/src/lib.rs"
}
}
},
"range": {
"end": {
"character": 1,
"line": 11
},
"start": {
"character": 0,
"line": 9
}
}
},
{
"data": {
"impls": {
"position": {
"character": 0,
"line": 13
},
"textDocument": {
"uri": "file:///e%3A/dev/src/se4_core/crates/se4_db/src/lib.rs"
}
}
},
"range": {
"end": {
"character": 1,
"line": 16
},
"start": {
"character": 0,
"line": 13
}
}
}
]
[Trace - 18:23:18] Received response 'textDocument/codeLens - (26)' in 16762ms.
Result: [
{
"data": {
"impls": {
"position": {
"character": 0,
"line": 9
},
"textDocument": {
"uri": "file:///e%3A/dev/src/se4_core/crates/se4_db/src/lib.rs"
}
}
},
"range": {
"end": {
"character": 1,
"line": 11
},
"start": {
"character": 0,
"line": 9
}
}
},
{
"data": {
"impls": {
"position": {
"character": 0,
"line": 13
},
"textDocument": {
"uri": "file:///e%3A/dev/src/se4_core/crates/se4_db/src/lib.rs"
}
}
},
"range": {
"end": {
"character": 1,
"line": 16
},
"start": {
"character": 0,
"line": 13
}
}
}
]
[Trace - 18:23:18] Received response 'codeLens/resolve - (25)' in 16762ms. Request failed: canceled by client (-32800).
[Trace - 18:23:18] Received response 'textDocument/foldingRange - (31)' in 14816ms.
Result: [
{
"endCharacter": 0,
"endLine": 5,
"kind": "imports",
"startCharacter": 0,
"startLine": 2
},
{
"endCharacter": 20,
"endLine": 11,
"startCharacter": 20,
"startLine": 9
},
{
"endCharacter": 20,
"endLine": 16,
"startCharacter": 20,
"startLine": 13
},
{
"endCharacter": 14,
"endLine": 35,
"startCharacter": 14,
"startLine": 18
},
{
"endCharacter": 99,
"endLine": 26,
"startCharacter": 99,
"startLine": 19
},
{
"endCharacter": 83,
"endLine": 34,
"startCharacter": 83,
"startLine": 28
}
]
[Trace - 18:23:18] Received response 'textDocument/codeLens - (33)' in 14768ms.
Result: [
{
"data": {
"impls": {
"position": {
"character": 0,
"line": 9
},
"textDocument": {
"uri": "file:///e%3A/dev/src/se4_core/crates/se4_db/src/lib.rs"
}
}
},
"range": {
"end": {
"character": 1,
"line": 11
},
"start": {
"character": 0,
"line": 9
}
}
},
{
"data": {
"impls": {
"position": {
"character": 0,
"line": 13
},
"textDocument": {
"uri": "file:///e%3A/dev/src/se4_core/crates/se4_db/src/lib.rs"
}
}
},
"range": {
"end": {
"character": 1,
"line": 16
},
"start": {
"character": 0,
"line": 13
}
}
}
]
[Trace - 18:23:18] Received response 'textDocument/codeLens - (35)' in 14765ms.
Result: [
{
"data": {
"impls": {
"position": {
"character": 0,
"line": 9
},
"textDocument": {
"uri": "file:///e%3A/dev/src/se4_core/crates/se4_db/src/lib.rs"
}
}
},
"range": {
"end": {
"character": 1,
"line": 11
},
"start": {
"character": 0,
"line": 9
}
}
},
{
"data": {
"impls": {
"position": {
"character": 0,
"line": 13
},
"textDocument": {
"uri": "file:///e%3A/dev/src/se4_core/crates/se4_db/src/lib.rs"
}
}
},
"range": {
"end": {
"character": 1,
"line": 16
},
"start": {
"character": 0,
"line": 13
}
}
}
]
[Trace - 18:23:18] Received response 'rust-analyzer/onEnter - (37)' in 14589ms.
No result returned.
[Trace - 18:23:18] Received response 'rust-analyzer/onEnter - (38)' in 14357ms.
No result returned.
No problem! I'm afraid I can't really help with the underlying issue.
DJMcNab
on 26 May 2019
It's a know problem, I hope to look into this soon.
The crux of the issue is that we don't implement any kind of request prioritization, so things like "handle enter" could be blocked on the background analysis
matklad
on 27 May 2019
@matklad - I'm still seeing this issue with the latest rust-analyzer
jonathandturner
on 29 May 2019
I'm also experiencing this issue quite commonly. Will gladly help if pointed in the right direction :)
kiljacken
on 29 May 2019
@kiljacken the steps to handle this problem:
- find out why it is slow, by inserting
profile("foo")calls - write a heavy test that shows the issue
- implement a fix
https://github.com/rust-analyzer/rust-analyzer/pull/1334 contains all those steps
Docs for our profiling infra are here: https://github.com/rust-analyzer/rust-analyzer/blob/master/docs/dev/README.md#profiling
matklad
on 29 May 2019
To clarify, on the high level, the problem isn't that handling Enter is slow, the problem is that handling Enter is blocked on some other stuff, and we should make sure that "other stuff" is properly canceled or does not block high-priority operations in the first place.
Another pointer would be our main loop:
Here, you can see on the highest level the order and timings of various events.
matklad
on 29 May 2019
Also, setting rust-analyzer.enableEnhancedTyping: false in the settings should completely disable our hijacking of enter to work around the issue, but we really should fix this: ability to features, which blocks user typing, fast enough is important to have in excellent language server :)
matklad
on 29 May 2019
I also started experiencing this a couple of days ago. The one thing that a text editor should be able to do flawlessly is handle my keystrokes, so needless to say, it's very frustrating when it does not. I can confirm that the issue is present on commit 854dac335d3e8295fba637ad6413d952e6b973ef. I haven't yet tried whether the issue persists with #1334 or with rust-analyzer.enableEnhancedTyping: false.
ghost
on 29 May 2019
I've looked into this, and, while I can't reproduce mulit-seconds hangs after #1334, I've fixed a couple of potential problems:
https://github.com/rust-analyzer/rust-analyzer/pull/1341
https://github.com/rust-analyzer/rust-analyzer/pull/1343
- we now have better perf logging in our main loop. We also show timings for the last ten requests in the status page:
(onEnter is the request this issue is about)
preveously, we tried to run GC before each request, which doens't make much sense. Now we GC after we've send a response
we now try to cancel pending background tasks when handling realtime requests like on Enter
I wonder if folks still can reproduce the problem after cb21a219987eac0f8dc08f0c858e8a7154fccd04
matklad
on 29 May 2019
Yes, I can still reproduce it. If you open https://github.com/wycats/nushell and open src/commands/split.rs, try to hit enter towards the top of the file. Especially if you tell it to run cargo check, I'm seeing pretty long delays after hitting enter. Sometimes the delays are multiple seconds.
jonathandturner
on 29 May 2019
I'm also looking at the "Rust Analyzer Language Server Trace" and don't see any output like you mention above. It's possible I'm not installing something correctly? I've been using cargo install-lsp followed by cargo install-code.
jonathandturner
on 29 May 2019
and don't see any output like you mention above.
The screenshot is from Rust Analyzer: Status VS Code command.
The hierarchical profiling is printed only if you set RA_PROFILE env var. RA_PROFILE=*>16 should show everything longer than 16 milliseconds.
matklad
on 29 May 2019
That's some of my numbers, though I'm definitely seeing delays longer than 1/3rd of a second.
jonathandturner
on 29 May 2019
This is more like it. These are the numbers I see on a fresh startup.
jonathandturner
on 29 May 2019
Just wondering, can a user request trigger a long-running computation (due to the lazy nature of RA) that isn't attributed properly in the profiler?
EDIT: E.g. I open a file and the highlighter wants semanatic information, which triggers analysis of most of the code in the project, and bad luck if you're opening it from a network share.
lnicola
on 29 May 2019
Just wondering, can a user request trigger a long-running computation (due to the lazy nature of RA) that isn't attributed properly in the profiler?
That is possible, though most of the stuff should be profiled. The notable thing which takes time, but is not present in the profile is salsa's overhead for validation, see https://salsa.zulipchat.com/#narrow/stream/145099-general/topic/Some.20Profiling.20data/near/166644275.
Though ideally this shouldn't be a problem. Rust Analyzer is explicitly architectured with arbitrary-long background computations in mind, so what should happen in this case is that, while one thread computes long-running task, another thread handles on-enter. After that, the client sends changes from on-enter, and the long-running task is automatically canceled.
But, as we clearly from profile data, the theory does not work in practice :D
My next hypothesis is that we handle onEnter asynchronously, so we recieve request and send response on different event loop turns, and something in between blocks the event loop. I'll try to handle onEnter synchronously, on the same turn of the event loop: really, there's no reason to offload it to background thread, and this naturally gives us that "task prioritization" I alluded to before.
matklad
on 29 May 2019
and something in between blocks the event loop
Found it! It's salsa!
Specifically, what I am seeing is this:
136ms - diagnostics
131ms - crate_def_map_query
131ms - collect_defs
131ms - collect_defs/populate-prelude
131ms - crate_def_map_query
131ms - collect_defs
131ms - collect_defs/populate-prelude
3ms - parse_query (1 calls)
118ms - main_loop_inner/loop-turn
118ms - RootDatabase::apply_change
118ms - RootDatabase::apply_change/cancellation
diagnostics kick in after a change and compute name resolution. We see that something has changed, so we kick nameres for the current crate (which, really shouldn't be the case I think for adding a blank like, but that's a separate issue). That name res kicks resolution of other crates, notably of std, in collect_defs/populate-prelude. Not however that this is the leaf entry of profiling three! That means that 131 milliseconds are spend entirely inside salsa, to verify that nothing has changed. And the problem here is that we can't cancel verification process, so wee need to spend the whole of 131 milliseconds. That's why RootDatabase::apply_change/cancellation takes 118ms as well: it blocks waiting for that non-cancellable block inside diagnostics to finish.
matklad
on 29 May 2019
which, really shouldn't be the case I think for adding a blank like, but that's a separate issue
The reason for that is if we happen to cancel a subquery when the parent query is validated, we completely remove the parent query, instead of marking it as not-validated
matklad
on 29 May 2019
Is there an issue in Salsa to track this slowness?
Edit: or, if it is unavoidable (which I doubt based on your comment), to discuss what we can do to make it better on our end.
DJMcNab
on 29 May 2019
Closed by https://github.com/rust-analyzer/rust-analyzer/pull/1348, I hope :sweat_smile:
If you still see hangs after that, please reopen :-)
Is there an issue in Salsa to track this slowness?
no, but I've found a work-around, and we are discussing stuff in Zulip:
https://salsa.zulipchat.com/#narrow/stream/145099-general/topic/Some.20Profiling.20data and https://salsa.zulipchat.com/#narrow/stream/184114-rfcs.2Fdrafts-and-proposals/topic/mutable.20constants
matklad
on 30 May 2019
Still seeing it.
and
To repro, if you open the project above, enable "cargo watch" and then press enter inside the file while analysis is running.
jonathandturner
on 30 May 2019
On my laptop nothing else works fine while cargo check is running. Not even my mouse cursor, at times.
lnicola
on 30 May 2019
@jonathandturner what happens if you disable cargo watch though? cargo watch just runs Cargo in the background, and I imagine that can, by default, consume all CPUs....
matklad
on 30 May 2019
Without cargo watch:
and
jonathandturner
on 30 May 2019
I'm not using cargo watch, and I've had a few times that pressing enter felt really slow (I updated rust-analyzer today for the first time in a couple months). The most recent time:
requests:
842 textDocument/completion 354ms
849 textDocument/foldingRange 652ms
850 textDocument/codeAction 652ms
851 rust-analyzer/onEnter 652ms
852*textDocument/foldingRange 1ms
835 textDocument/completion 155ms
836 textDocument/completion 150ms
837 textDocument/foldingRange 0ms
838 textDocument/completion 411ms
839 textDocument/foldingRange 1ms
Edit: another time that seemed like 5 to 10 seconds:
requests:
1758 textDocument/completion 2787ms
1779 textDocument/completion 1490ms
1794 textDocument/foldingRange 1846ms
1797 rust-analyzer/onEnter 1842ms
1798*textDocument/foldingRange 1ms
1745 textDocument/foldingRange 1ms
1746 textDocument/codeAction 50ms
1747 textDocument/foldingRange 0ms
1748 textDocument/codeAction 131ms
1749 textDocument/foldingRange 1ms
jminer
on 30 May 2019
Status update:
I still haven't looked closely into this particular issue, as I can't get a reproduction on a local machine.
My current thoughts:
- this could be caused by GC (which is stop-the-world at the moment). LRU work should help here, and we could move GC off the event-loop thread
- pauses during initial load of the project could be caused by overloading system initially or loading things in non-optimal order (libraries before the main code). But the above traces show pauses after initial load
- maybe we are just overloading the whole system with too many threads (this shouldn't be the issue though, if threads don't block each other)
- a though that occurred to me right now: I am testing this on a laptop with SSD, I wonder if spinning disks drastically change the latency picture here
matklad
on 11 Jun 2019
Status update: @jminer and @lnicola discovered that this is a windows specific issues, caused by the fact that our cancellation mechanism triggers collection of backtraces. I am pushing a hot-fix for this in https://github.com/rust-analyzer/rust-analyzer/pull/1401 (basically, don't force backtrace), the proper solution is presumably https://github.com/rust-analyzer/rust-analyzer/issues/1400 (we need to verify though that just panic::resume_unwind does not trigger backtrace)
matklad
on 13 Jun 2019
we need to verify though that just panic::resume_unwind does not trigger backtrace
It doesn't print anything, so no backtrace either. I used it in compiletest (https://github.com/rust-lang/rust/pull/59990) to prevent the unnecessary panic message when a test failed.
bjorn3
on 13 Jun 2019
Ok, as an old Russian tale goes,
For the third time Alyosha has closed the issue
If you are still seeing this, please reopen :)
matklad
on 15 Jun 2019
Related issues
matklad
路
24Comments
schungx
路
38Comments
dakyskye
路
23Comments
Progdrasil
路
28Comments
Redoubts
路
45Comments
Most helpful comment
Ok, as an old Russian tale goes,
If you are still seeing this, please reopen :)