`rustfmt` on save takes unusually long

[Aloso]

When I open a project in VS Code, modify a file and save, it takes several seconds to format the file:

Invoking cargo fmt manually only takes a few milliseconds.

The bug only appears when saving a file shortly after opening VS Code, while rust-analyzer is still busy analyzing the project (which takes ~2-3 min for my project).

EDIT:

The trace contains these lines:

[Trace - 15:58:29] Sending request 'textDocument/formatting - (25)'.
[Trace - 15:58:33] Received response 'textDocument/formatting - (25)' in 3912ms.

Click to see trace

[Trace - 15:58:24] Sending request 'initialize - (0)'.
[Trace - 15:58:24] Received response 'initialize - (0)' in 42ms.
[Trace - 15:58:24] Sending notification 'initialized'.
[Trace - 15:58:24] Sending notification 'textDocument/didOpen'.
[Trace - 15:58:24] Sending request 'rust-analyzer/inlayHints - (1)'.
[Trace - 15:58:25] Sending request 'textDocument/documentSymbol - (2)'.
[Trace - 15:58:25] Sending notification '$/cancelRequest'.
[Trace - 15:58:25] Sending request 'rust-analyzer/inlayHints - (3)'.
[Trace - 15:58:25] Received request 'client/registerCapability - (1)'.
[Trace - 15:58:25] Sending response 'client/registerCapability - (1)'. Processing request took 1ms
[Trace - 15:58:25] Received request 'window/workDoneProgress/create - (2)'.
[Trace - 15:58:25] Sending response 'window/workDoneProgress/create - (2)'. Processing request took 0ms
[Trace - 15:58:25] Received notification '$/progress'.
[Trace - 15:58:25] Received response 'rust-analyzer/inlayHints - (1)' in 192ms. Request failed: content modified (-32801).
[Trace - 15:58:25] Received response 'textDocument/documentSymbol - (2)' in 104ms. Request failed: content modified (-32801).
[Trace - 15:58:25] Sending request 'rust-analyzer/inlayHints - (4)'.
[Trace - 15:58:25] Received notification '$/progress'.
[Trace - 15:58:25] Received notification '$/progress'.
[Trace - 15:58:25] Received notification '$/progress'.
[Trace - 15:58:25] Received notification '$/progress'.
[Trace - 15:58:25] Received response 'rust-analyzer/inlayHints - (4)' in 4ms. Request failed: content modified (-32801).
[Trace - 15:58:25] Received response 'rust-analyzer/inlayHints - (3)' in 132ms. Request failed: content modified (-32801).
[Trace - 15:58:25] Received notification 'textDocument/publishDiagnostics'.
[Trace - 15:58:25] Sending request 'rust-analyzer/inlayHints - (5)'.
[Trace - 15:58:25] Received response 'rust-analyzer/inlayHints - (5)' in 3ms.
[Trace - 15:58:25] Sending request 'textDocument/semanticTokens/range - (6)'.
[Trace - 15:58:25] Received response 'textDocument/semanticTokens/range - (6)' in 4ms.
[Trace - 15:58:25] Sending request 'rust-analyzer/inlayHints - (7)'.
[Trace - 15:58:25] Received response 'rust-analyzer/inlayHints - (7)' in 1ms.
[Trace - 15:58:25] Sending request 'textDocument/foldingRange - (8)'.
[Trace - 15:58:25] Sending request 'textDocument/codeLens - (9)'.
[Trace - 15:58:25] Received response 'textDocument/foldingRange - (8)' in 2ms.
[Trace - 15:58:25] Received response 'textDocument/codeLens - (9)' in 3ms.
[Trace - 15:58:25] Received notification '$/progress'.
[Trace - 15:58:25] Sending request 'textDocument/semanticTokens - (10)'.
[Trace - 15:58:25] Received response 'textDocument/semanticTokens - (10)' in 8ms.
[Trace - 15:58:25] Sending request 'rust-analyzer/onEnter - (11)'.
[Trace - 15:58:25] Received response 'rust-analyzer/onEnter - (11)' in 2ms.
[Trace - 15:58:25] Sending notification 'textDocument/didChange'.
[Trace - 15:58:25] Sending request 'rust-analyzer/inlayHints - (12)'.
[Trace - 15:58:25] Received response 'rust-analyzer/inlayHints - (12)' in 11ms.
[Trace - 15:58:25] Received notification 'textDocument/publishDiagnostics'.
[Trace - 15:58:25] Sending request 'rust-analyzer/onEnter - (13)'.
[Trace - 15:58:25] Received response 'rust-analyzer/onEnter - (13)' in 1ms.
[Trace - 15:58:25] Sending notification 'textDocument/didChange'.
[Trace - 15:58:25] Sending request 'rust-analyzer/inlayHints - (14)'.
[Trace - 15:58:25] Received notification 'textDocument/publishDiagnostics'.
[Trace - 15:58:25] Received response 'rust-analyzer/inlayHints - (14)' in 23ms.
[Trace - 15:58:26] Sending request 'textDocument/semanticTokens - (15)'.
[Trace - 15:58:26] Received response 'textDocument/semanticTokens - (15)' in 4ms.
[Trace - 15:58:26] Sending request 'textDocument/foldingRange - (16)'.
[Trace - 15:58:26] Sending request 'rust-analyzer/onEnter - (17)'.
[Trace - 15:58:26] Received response 'rust-analyzer/onEnter - (17)' in 1ms.
[Trace - 15:58:26] Received response 'textDocument/foldingRange - (16)' in 2ms.
[Trace - 15:58:26] Sending notification 'textDocument/didChange'.
[Trace - 15:58:26] Sending request 'rust-analyzer/inlayHints - (18)'.
[Trace - 15:58:26] Received response 'rust-analyzer/inlayHints - (18)' in 9ms.
[Trace - 15:58:26] Received notification 'textDocument/publishDiagnostics'.
[Trace - 15:58:26] Sending request 'rust-analyzer/onEnter - (19)'.
[Trace - 15:58:26] Received response 'rust-analyzer/onEnter - (19)' in 1ms.
[Trace - 15:58:26] Sending notification 'textDocument/didChange'.
[Trace - 15:58:26] Sending request 'rust-analyzer/inlayHints - (20)'.
[Trace - 15:58:26] Received notification 'textDocument/publishDiagnostics'.
[Trace - 15:58:26] Received response 'rust-analyzer/inlayHints - (20)' in 8ms.
[Trace - 15:58:26] Sending request 'textDocument/semanticTokens - (21)'.
[Trace - 15:58:26] Received response 'textDocument/semanticTokens - (21)' in 12ms.
[Trace - 15:58:26] Sending request 'textDocument/foldingRange - (22)'.
[Trace - 15:58:26] Received response 'textDocument/foldingRange - (22)' in 1ms.
[Trace - 15:58:26] Sending request 'textDocument/codeLens - (23)'.
[Trace - 15:58:26] Received response 'textDocument/codeLens - (23)' in 9ms.
[Trace - 15:58:26] Sending request 'textDocument/documentSymbol - (24)'.
[Trace - 15:58:26] Received response 'textDocument/documentSymbol - (24)' in 2ms.
[Trace - 15:58:27] Received notification '$/progress'.
[Trace - 15:58:28] Received notification '$/progress'.
[Trace - 15:58:28] Received notification '$/progress'.
[Trace - 15:58:28] Received notification '$/progress'.
[Trace - 15:58:28] Received notification '$/progress'.
[Trace - 15:58:28] Received notification '$/progress'.
[Trace - 15:58:28] Received notification '$/progress'.
[Trace - 15:58:28] Received notification 'textDocument/publishDiagnostics'.
[Trace - 15:58:28] Received notification 'textDocument/publishDiagnostics'.
[Trace - 15:58:28] Received notification 'textDocument/publishDiagnostics'.
[Trace - 15:58:28] Received notification 'textDocument/publishDiagnostics'.
[Trace - 15:58:28] Received notification '$/progress'.
[Trace - 15:58:29] Sending request 'textDocument/formatting - (25)'.
[Trace - 15:58:33] Received response 'textDocument/formatting - (25)' in 3912ms.
[Trace - 15:58:33] Sending notification 'textDocument/didChange'.
[Trace - 15:58:33] Sending request 'rust-analyzer/inlayHints - (26)'.
[Trace - 15:58:33] Sending notification 'textDocument/didSave'.
[Trace - 15:58:33] Received notification 'textDocument/publishDiagnostics'.
[Trace - 15:58:33] Received notification '$/progress'.
[Trace - 15:58:34] Sending request 'textDocument/foldingRange - (27)'.
[Trace - 15:58:34] Received response 'textDocument/foldingRange - (27)' in 22ms.
[Trace - 15:58:34] Received notification 'textDocument/publishDiagnostics'.
[Trace - 15:58:34] Received notification 'textDocument/publishDiagnostics'.
[Trace - 15:58:34] Sending request 'textDocument/codeLens - (28)'.
[Trace - 15:58:34] Received response 'textDocument/codeLens - (28)' in 3ms.
[Trace - 15:58:34] Sending request 'textDocument/semanticTokens - (29)'.
[Trace - 15:58:34] Received notification 'textDocument/publishDiagnostics'.
[Trace - 15:58:34] Received notification 'textDocument/publishDiagnostics'.
[Trace - 15:58:34] Received notification '$/progress'.
[Trace - 15:58:34] Sending request 'textDocument/documentSymbol - (30)'.
[Trace - 15:58:34] Sending notification 'workspace/didChangeWatchedFiles'.
[Trace - 15:58:34] Received response 'textDocument/documentSymbol - (30)' in 2ms.
[Trace - 15:58:34] Received notification '$/progress'.
[Trace - 15:58:34] Received notification '$/progress'.
[Trace - 15:58:42] Received response 'rust-analyzer/inlayHints - (26)' in 8571ms.
[Trace - 15:58:42] Received notification 'textDocument/publishDiagnostics'.
[Trace - 15:58:42] Received response 'textDocument/semanticTokens - (29)' in 8373ms.

[lnicola]

I also noticed this. I think it happens when RA is busy, but it's even worse when it panics, because the formatter never finishes. @Aloso, maybe check if you have any panics in one of the Output sections.

[Aloso]

@lnicola It seems there was no panic. I added the trace in the issue.

[Speedy37]

Same here, but it happens for every edits

Trace - 00:57:28] Received response 'textDocument/codeAction - (47)' in 60704ms. Request failed: content modified (-32801).
[Trace - 00:57:28] Received response 'textDocument/codeAction - (55)' in 36017ms. Request failed: canceled by client (-32800).
[Trace - 00:57:28] Received response 'rust-analyzer/inlayHints - (50)' in 36256ms. Request failed: canceled by client (-32800).
[Trace - 00:57:28] Received response 'textDocument/semanticTokens - (52)' in 36185ms. Request failed: content modified (-32801).
[Trace - 00:57:28] Received response 'textDocument/codeLens - (54)' in 36048ms. Request failed: content modified (-32801).
[Trace - 00:57:28] Received response 'textDocument/semanticTokens/range - (51)' in 36196ms. Request failed: canceled by client (-32800).
[Trace - 00:57:28] Received response 'textDocument/foldingRange - (53)' in 36099ms. Request failed: canceled by client (-32800).
[Trace - 00:57:28] Received response 'textDocument/definition - (60)' in 22965ms. Request failed: canceled by client (-32800).
[Trace - 00:57:28] Received response 'textDocument/definition - (61)' in 22325ms. Request failed: canceled by client (-32800).
[Trace - 00:57:28] Received response 'rust-analyzer/inlayHints - (56)' in 27454ms. Request failed: canceled by client (-32800).
[Trace - 00:57:28] Received response 'textDocument/definition - (62)' in 21216ms. Request failed: content modified (-32801).
[Trace - 00:57:28] Received response 'textDocument/codeLens - (59)' in 27250ms. Request failed: content modified (-32801).
[Trace - 00:57:28] Received response 'textDocument/semanticTokens/range - (57)' in 27395ms. Request failed: content modified (-32801).
[Trace - 00:57:28] Received response 'textDocument/foldingRange - (58)' in 27301ms. Request failed: canceled by client (-32800).
[Trace - 00:57:28] Received response 'textDocument/formatting - (64)' in 20880ms. Request failed: canceled by client (-32800).
[Trace - 00:57:28] Received response 'textDocument/foldingRange - (66)' in 20716ms.
[Trace - 00:57:28] Received response 'textDocument/documentSymbol - (68)' in 18792ms.
[Trace - 00:57:28] Received response 'textDocument/codeLens - (67)' in 20683ms.
[Trace - 00:57:28] Received response 'textDocument/semanticTokens/range - (65)' in 20841ms.
[Trace - 00:57:28] Received response 'textDocument/formatting - (69)' in 18355ms.

Could it be possible to package rust-analyser with symbols so it's easy to debug/profile it?

[Speedy37]

I can't reproduce on master, but I reproduce immediately on release.
So I guess #4060 fix this too.

[matklad]

@flodiebold I haven't looked into this, but do you have an idea why slow chalk blocked other requests? Could it be the case that some check_canceled() calls are missing?

[flodiebold]

Yes, in the recursive solver we probably don't have any cancellation checks. We could add them to the RustIrDatabase methods for now; I hope will be able to 'properly' fix it when we integrate the recursive solver more directly with Salsa.

[Aloso]

So I guess #4060 fix this too.

@Speedy37 the bug is not fixed on the latest nightly build.

[Speedy37]

Ok so I guess, It is not the same case as mine. I did encounter some 2/3seconds hangs today.
But before #4060 it was just unusable.
I can let the profiler on tomorrow and try to catch some hangs hotspots/backtrace if that would help.
PS: I'm on windows with a locally applied mimalloc global allocator.

[Diggsey]

I have this problem too: can't formatting run in parallel with other RA tasks? There's no reason that "check" should block a file from being saved.

[virtualritz]

I have this issue randomly on VSCode on macOS. It is extremely annoying. It can frequently take over a minute for the save to go through.

[agg23]

This is still occurring. The only thing that seems to help is restarting VSCode entirely, but it doesn't always work. It also seems to occur in batches; some change to code or environment will cause it to occur for some period of time, after which everything runs smoothly once again.

[sazzer]

I'm still getting this, with Rust "1.62.0-nightly (4c60a0ea5 2022-05-04)" and Rust Analyzer 0.3.1051-darwin-arm64. Sometimes the only thing that fixes it is rebooting the entire machine - not just VSCode! :(

[jason1105]

I'm still getting this, with Rust "1.62.0-nightly (4c60a0ea5 2022-05-04)" and Rust Analyzer 0.3.1051-darwin-arm64. Sometimes the only thing that fixes it is rebooting the entire machine - not just VSCode! :(

I've met the same problem. At the same time I found Rust-Analyzer extension is upgrading, so I took several minutes for waitting it finish, then problem was solved : )