Formatting (on save) sometimes takes a long time

[andys8]

I noticed format on save often is hitting the 0.5s timeout with larger files (coc, vim). Often it works with the same file, but sometimes save / format takes much longer.

Formatting the same file with purty on command line is consistently fast.

  Time (mean ± σ):      34.9 ms ±  14.3 ms    [User: 59.8 ms, System: 57.9 ms]
  Range (min … max):    18.3 ms …  86.1 ms    100 runs

From the outside it looks like either format is triggering save to take longer or triggering something else. Or format is failing because of a different reason we hit the timeout.

This issue is missing more actionable information, but currently I'm not aware what and how to collect. It seems to be reproducible for larger files, by configuring format on save and hitting save multiple times.

[nwolverson]

That's odd. It would be interesting to know if anybody has seen this on something outside of coc.

Can you see if there's anyting interesting in the log? Not sure if we log anything about formatting specifically, but if the LSP communication is visible around some slow saves you can see what specific requests are made. Should be able to see when the format request is made and the text edit is made, if that is indeed what is taking the time

[andys8]

Yes, I think I need to place some log statements and timing in there and have a look again.

Without that: Is this issue not the case with other editors?

[nwolverson]

Rather than placing log statements, I'd expect that you can get LSP communication trace from coc somehow?

[andys8]

I'll look into it. I'd expect that too, but I'd expect it to be not very fine grained.

[andys8]

This is the log from opening a file and hitting save some times. Some of them succeeded, some of them ran into the timeout. I was using "trace.server": "verbose" but there isn't a lot of information. In the beginning the language server wasn't ready, but that's not what I'm talking about.

## versions

vim version: VIM - Vi IMproved 8.2 8022347
node version: v14.9.0
coc.nvim version: 0.0.80-6e5a2aaeb5
coc.nvim directory: /home/andreas/.vim/plugged/coc.nvim
term: dumb
platform: linux

## Log of coc.nvim

2021-01-30T15:15:31.641 INFO (pid:86381) [services] - registered service "languageserver.elmLS"
2021-01-30T15:15:31.642 INFO (pid:86381) [services] - registered service "languageserver.haskell-language-server"
2021-01-30T15:15:31.642 INFO (pid:86381) [services] - registered service "languageserver.bash"
2021-01-30T15:15:31.642 INFO (pid:86381) [services] - registered service "languageserver.dockerfile"
2021-01-30T15:15:31.642 INFO (pid:86381) [services] - registered service "languageserver.purescript"
2021-01-30T15:15:31.684 INFO (pid:86381) [services] - registered service "diagnostic-languageserver"
2021-01-30T15:15:31.856 INFO (pid:86381) [language-client-index] - cSpell started with 86392
2021-01-30T15:15:32.006 WARN (pid:86381) [attach] - Plugin not ready when received "runCommand" [ 'coc-helper.internal.didVimEvent_1', 'BufDelete', 2 ]
2021-01-30T15:15:32.007 WARN (pid:86381) [attach] - Plugin not ready when received "runCommand" [ 'coc-helper.internal.didVimEvent_2', 'BufDelete', 2 ]
2021-01-30T15:15:32.200 INFO (pid:86381) [plugin] - coc.nvim 0.0.80-6e5a2aaeb5 initialized with node: v14.9.0 after 626ms
2021-01-30T15:15:33.351 INFO (pid:86381) [attach] - receive notification: doAutocmd [ 1 ]
2021-01-30T15:15:33.363 INFO (pid:86381) [attach] - receive notification: runCommand [ 'coc-helper.internal.didVimEvent_1', 'BufWipeout', 2 ]
2021-01-30T15:15:33.364 INFO (pid:86381) [attach] - receive notification: runCommand [ 'coc-helper.internal.didVimEvent_2', 'BufWipeout', 2 ]
2021-01-30T15:15:33.368 INFO (pid:86381) [attach] - receive notification: runCommand [ 'coc-helper.internal.didVimEvent_1', 'BufWipeout', 1 ]
2021-01-30T15:15:33.368 INFO (pid:86381) [attach] - receive notification: runCommand [ 'coc-helper.internal.didVimEvent_2', 'BufWipeout', 1 ]
2021-01-30T15:15:33.385 INFO (pid:86381) [attach] - receive notification: doAutocmd [ 1 ]
2021-01-30T15:15:33.443 INFO (pid:86381) [attach] - receive notification: runCommand [ 'coc-helper.internal.didVimEvent_2', 'CocDiagnosticChange' ]
2021-01-30T15:15:33.458 INFO (pid:86381) [services] - purescript state change: stopped => starting
2021-01-30T15:15:33.465 INFO (pid:86381) [language-client-index] - Language server "languageserver.purescript" started with 86451
2021-01-30T15:15:33.565 INFO (pid:86381) [services] - purescript state change: starting => running
2021-01-30T15:15:33.568 INFO (pid:86381) [services] - service languageserver.purescript started
2021-01-30T15:15:34.310 INFO (pid:86381) [attach] - receive request: CocAutocmd [ 'BufWritePre', 3 ]
2021-01-30T15:15:35.591 INFO (pid:86381) [attach] - receive request: CocAutocmd [ 'BufWritePre', 3 ]
2021-01-30T15:15:38.424 INFO (pid:86381) [attach] - receive request: CocAutocmd [ 'BufWritePre', 3 ]
2021-01-30T15:15:39.814 INFO (pid:86381) [attach] - receive request: CocAutocmd [ 'BufWritePre', 3 ]
2021-01-30T15:15:41.074 INFO (pid:86381) [attach] - receive request: CocAutocmd [ 'BufWritePre', 3 ]
2021-01-30T15:15:42.347 INFO (pid:86381) [attach] - receive request: CocAutocmd [ 'BufWritePre', 3 ]
2021-01-30T15:15:43.997 INFO (pid:86381) [attach] - receive request: CocAutocmd [ 'BufWritePre', 3 ]
2021-01-30T15:15:45.355 INFO (pid:86381) [attach] - receive request: CocAutocmd [ 'BufWritePre', 3 ]
2021-01-30T15:15:49.715 INFO (pid:86381) [attach] - receive notification: showInfo []

[andys8]

I'm now looking into the code about import organization and formatting. Especially because there is an open issue where purty formatting and purescript imports differ: https://gitlab.com/joneshf/purty/-/issues/210

I stumbled into https://github.com/nwolverson/purescript-language-server/issues/120 ;)

[nwolverson]

That logging doesn't seem to show any LSP logging or even the window/logMessage "logging" from the language server. The relevant log would contain the textDocument/formatting request at a minimum. Looks like we're not logging anything from the LS side for a formatting request (unless erroring) though.

Maybe worth looking at https://github.com/neoclide/coc.nvim/wiki/Debug-language-server You can set purescript.trace.server to verbose similarly to the suggestion on that page to get the LSP trace

[andys8]

I did set set "trace.server". But I'm with you. The log looks like something went wrong. There isn't a lot in there. Can of course be wrongly configured in my side.

With the pushed changes of #120 I'll have a second look when I've time in the future :)

[andys8]

I did some research. I'm still missing logs and timings, so I'm only looking at code.

formatWithPurty is using spawn

https://github.com/andys8/purescript-language-server/blob/8eb960c7b19366ea87554bfcccb41525ac4cc07d/src/LanguageServer/IdePurescript/Formatting.purs#L41

It will use getEnv in multiple places

Then findBins will look for binaries.

https://github.com/kRITZCREEK/purescript-psc-ide/blob/c813caa4aec6beef9677b4e68b8bc724f3b4c308/src/PscIde/Server.purs#L136

It will run which and find two binaries in my case. which should be fast (2 ms).

For each binary it will try to invoke it with --version

https://github.com/kRITZCREEK/purescript-psc-ide/blob/c813caa4aec6beef9677b4e68b8bc724f3b4c308/src/PscIde/Server.purs#L143-L144

This will cost round about 100 ms and fail for purty, because it expects purty version, not purty --version.

I commented out the search for binaries in this commit:

https://github.com/andys8/purescript-language-server/commit/8ced512b425cda41abedec4d1ac1d58562a26003#diff-53c566b10adcae38675bc3172fc5c76bb21ce18b999b5a80ce9eb1a5e30ca250

It will then run purty and other commands as they are. My first impression is that this does speed up things. It's still possible to hit 500ms timeouts on save, but it happens less likely on large files.

I still think there is a reason where build and purty could influence each other, and/or purty in itself is slow. This is most likely not in the hands of this project.

Ideas

• First verify with numbers that path / version search takes time
• Then: Find paths and versions of binaries on startup
• Or: Cache / memoize path and version search in spawn

[andys8]

With spago and webpack running in other terminals I can see very high times in vs code, too

Without any other process running there seem to be still high latencies:

[Trace - 5:15:12 PM] Received response 'textDocument/foldingRange - (152)' in 1522ms.
Result: [
    {
        "startLine": 2,
        "endLine": 38,
        "startCharacter": 0,
        "endCharacter": 6,
        "kind": "imports"
    }
]

[Trace - 5:15:12 PM] Received response 'textDocument/codeAction - (153)' in 1486ms.
Result: []

Hitting save multiple times (with format on save) will show times like this:

With some seconds in between saves:

[Trace - 5:19:52 PM] Received response 'textDocument/formatting - (38)' in 321ms.
[Trace - 5:19:54 PM] Received response 'textDocument/formatting - (39)' in 477ms.
[Trace - 5:19:58 PM] Received response 'textDocument/formatting - (40)' in 235ms.

Hammering save:

[Trace - 5:21:01 PM] Received response 'textDocument/formatting - (43)' in 393ms.
[Trace - 5:21:01 PM] Received response 'textDocument/formatting - (44)' in 324ms.
[Trace - 5:21:02 PM] Received response 'textDocument/formatting - (46)' in 514ms.
[Trace - 5:21:09 PM] Received response 'textDocument/formatting - (51)' in 7012ms.

And with waiting and only hit save once, I still can see:

[Trace - 5:23:29 PM] Received response 'textDocument/formatting - (70)' in 559ms.

This means hitting 500ms is likely to happen on large files in any editor. The difference is that Vim/CoC will timeout by default. It also looks like aggressive behavior might lead to some kind of rebuild or cache invalidation which can result in very long times.

[nwolverson]

Sorry for my lack of followup @andys8 - I don't think there was ever an intention to do all the find/version dance with purty, that just came from lazily hooking into an existing codepath - the point of all that is that one of the most frequent support issues is using the wrong version of purs for purs ide server which conflicts to the one that is being used for builds due to PATH issues with the IDE etc, so doing this once as it happens on startup makes sense.

Not sure if it makes sense to do this for any other exec, I doubt it's useful

[andys8]

What do you think of the following logic:

if addNpmPath
then spawn "./node_modules/.bin/purty format -"
else spawn "purty format -"

Am I missing something or should this work just fine?

[nwolverson]

That would not be correct, that does not just add the npm bin to the PATH, it ignores the PATH entirely. If there is in fact no purty in the project path the behaviour will be changed.

I think we just need to update the PATH correctly but skip all the where and version junk - it's just a question of getting around to it

[andys8]

it ignores the PATH entirely

I think I might be not understanding something critical here. Why would that be? Could you help me out?

I'm currently using a fork with this change - as in "it's working for me and slightly faster" :

https://github.com/nwolverson/purescript-language-server/compare/master...andys8:andys8-fork

My assumption is that Node.ChildProcess.spawn is already using whatever is on the PATH. Why add something then? What am I missing to see?

[nwolverson]

addNpmPath is an option to add the npm dir to the PATH when launching tools (such as purs and the build command), because many people find that useful. I think spawn should use the path, so we should add the npm dir to the PATH variable when we call spawn, like the code on the left of that diff.

I would be surprised if getEnv was very slow; if it is measurably slow, we could cache it, but I think I have a simple observation that solves your issue - we seem to be updating the path even when that setting is turned off, we could just leave the defaults otherwise - then with that flag off you have the right side of your diff anyway.

(Still need to remove the version check/findbins stuff)

[andys8]

Now, I got it. Even if people set addNpmPath to true it wouldn't mean every binary (e.g. purty) is in there. Makes sense.

(Still need to remove the version check/findbins stuff)

Yep. I wouldn't say this is super slow, but I think it's measurable and not necessary. So that would be a nice improvement.

[nwolverson]

FYI I started working on this but set it down, I'll try to get around to it

[nwolverson]

@andys8 can you give a go with the latest (0.15.1)? I think the spawning is now ligher-weight, but there was an epic sidetrack trying to handle the case of purty not being present, which was causing the language server process to abruptly exit in my testing, so I may have lost track of the original issue.

[andys8]

I did update and it's working for me.

Will keep an eye open on times. I can still reproduce cases where saving takes multiple seconds. I'm not sure if this related to formatting or how it could lead to cache invalidation. I'd consider this issue closed and if can be boiled down to purescript-language-server, then a new issue with better information might be a good idea.

[nwolverson]

OK, good to hear its working as far as that goes, multiple seconds certainly seems like some funky business not just a little spawn time overhead.

There could certainly be some interaction with formatting on save, rebuild on save, and managing to save a couple of times in quick succession