Clojurians Log v2

I’m testing this from the branch and notice a significant time lag when navigating to code in my project. Never seen it before, but that could be because I am always jacked-in and nREPL is blistering fast. Will try with dev as well now.

It's not like this in the dev branch. It's in my work project. A cljs mobile app. Not huge, but not tiny either. Navigating to a project file when lsp is finished initializing takes several seconds (maybe five) on this branch, but is instant on dev. Navigating to the same file again is instant on both branches. Which might mean the lag is happening in clojure-lsp? @ericdallo

So, it’s only with project sources. Clojure core and libraries are instant. Also documentation hover is quick. Definition hovers are also quick, interestingly enough. And even after having looked at that the navigation is slow. That indicates that finding and reading the file is still quick, and something is going on between that and opening the file in vscode.

Yes. there it is. Actually not about looking it up a second time, but about opening the editor.

Demo

Never saw this lag @pez do you have a repro? Also we can check the clojure-lsp request/response to check the time between them

I can’t reproduce it in a some test project at least. Where do I find the logs?

@brandon.ringe may know better but I think for Calva there is a log output called clojure-lsp or something

maybe you need to enable some debug flag

I know I have had that log before. 😃

Trying here on MacOS, and the “Go/Show to Definition/Parameters” actions stopped working, I always get the no definition found for …. error “Find references” in the other hand is working fine, :confusedparrot: A Clojure (lein) project medium size

Check clojure-lsp log file

Where Can I find it? I was looking into:

/var/folders/9v/7gk7ycxn2l544kxbznw979kr0000gp/T/clojure-lsp.10969030960409803808.out

You can pass a :log-path to clojure-lsp config to always log to the same file

Seems to be the file I am looking at, but I found no errors log, should I try to look for something specific?

So no errors, you should check the same log I told PEZ to find, the request/response log between client<->server

I know you can get it via Calva, I just don't remember know, @brandon.ringe will know how to access it

The request/response log is in an Output channel called Clojure Language Client

Thanks for all this testing, everyone. Indeed, some things could be a result of updating clojure-lsp. Maybe I should have just stuck with the same version from the currently released Calva for this testing...

To isolate issues

I don’t have that output channel anymore. Not with dev either. Sticking to the same version as with dev sounds like a good idea.

I tried to replace the clojure-lsp binary inside the extension to the 2021.02.10-03.01.19 version (the one that was being used before), and it still is failing to navigate About the output channel I was able to get it’s logs when setting "clojure.trace.server": "verbose" on VsCode settings

@leoiacovini try to remove the .lsp/sqlite.db file and restart the server

Already did, no deal. Reverting back to the master version of Calva, makes things work again I am trying to bisect the problem, but it seems more related to the PR itself than to clojure-lsp. I am going to try to bump just the lsp version with Calva master and checks if something breaks

Yeah, just updating the JAR version of clojure-lsp still works fine

I added a section to the clojure-lsp doc about enabling and viewing the logs: https://calva.io/clojure-lsp/#troubleshooting

@leoiacovini Nice investigation :thinking_face:

I think it should log by default.

Would you mind putting your findings on the PR, so I can track them better?

Nice investigation indeed!

I think I was following the path of the other trace servers by not enabling the logging by default. The html, json, and typescript server tracing is off by default. Maybe in our case it does make sense to enable it by default, though.

Anyway, the lag with opening files that I experience is not there if I use 2021.02.10-03.01.19 in config.ts

Good to know it's not related to a code change in Calva

Yes, now back to latest clojure-lsp and the issue is back. Here’s a log from a navigation with the lag:

[Trace - 11:14:00 PM] Sending request 'textDocument/definition - (21)'.
[Trace - 11:14:00 PM] Received response 'textDocument/definition - (21)' in 10ms.
[Trace - 11:14:00 PM] Sending notification 'textDocument/didOpen'.
[Trace - 11:14:00 PM] Sending notification 'textDocument/didClose'.
[Trace - 11:14:01 PM] Sending request 'textDocument/definition - (22)'.
[Trace - 11:14:01 PM] Sending request 'textDocument/codeAction - (23)'.
[Trace - 11:14:03 PM] Received response 'textDocument/definition - (22)' in 2668ms.
[Trace - 11:14:03 PM] Received response 'textDocument/codeAction - (23)' in 2608ms.
[Trace - 11:14:03 PM] Received notification 'textDocument/publishDiagnostics'.
[Trace - 11:14:03 PM] Sending notification 'textDocument/didOpen'.
[Trace - 11:14:03 PM] Sending request 'textDocument/codeAction - (24)'.
[Trace - 11:14:03 PM] Sending request 'textDocument/documentSymbol - (25)'.
[Trace - 11:14:03 PM] Sending notification '$/cancelRequest'.
[Trace - 11:14:03 PM] Sending request 'textDocument/documentSymbol - (26)'.
[Trace - 11:14:04 PM] Sending request 'textDocument/codeAction - (27)'.
[Trace - 11:14:04 PM] Sending notification '$/cancelRequest'.
[Trace - 11:14:04 PM] Sending request 'textDocument/codeAction - (28)'.
[Trace - 11:14:04 PM] Sending notification '$/cancelRequest'.
[Trace - 11:14:06 PM] Received response 'textDocument/documentSymbol - (25)' in 2845ms. Request failed: The request (id: 25, method: 'textDocument/documentSymbol') has been cancelled (-32800).
[Trace - 11:14:06 PM] Received response 'textDocument/codeAction - (24)' in 2856ms. Request failed: The request (id: 24, method: 'textDocument/codeAction') has been cancelled (-32800).
[Trace - 11:14:06 PM] Received response 'textDocument/codeAction - (27)' in 2626ms. Request failed: The request (id: 27, method: 'textDocument/codeAction') has been cancelled (-32800).
[Trace - 11:14:06 PM] Received response 'textDocument/documentSymbol - (26)' in 2848ms.
[Trace - 11:14:06 PM] Received notification 'textDocument/publishDiagnostics'.
[Trace - 11:14:06 PM] Received response 'textDocument/codeAction - (28)' in 2514ms.
[Trace - 11:14:07 PM] Sending request 'textDocument/codeAction - (29)'.
[Trace - 11:14:07 PM] Received response 'textDocument/codeAction - (29)' in 147ms.

I think we would need the request and response params from the textDocument/definition that is not working

Oh, wow. @ericdallo Received response 'textDocument/documentSymbol - (25)' in 2845ms - those documentSymbol and codeAction responses are taking a really long time

Yeah, would be helpful. Can set logging to verbose for that.

Oh I see request failed too. hmm

still the documentSymbol should not block a textDocument/definition on client side, but yeah, it's weird to take that time, maybe you have a huge buffer/file content?

The files are not huge, if the question was for me.

I see, could you provide a minimal repro with that bug? So I can test it with emacs client and understand the issue

Before we go down the rabbit hole further, @pez do you think I should just keep the clojure-lsp version set to one that works fine for this PR? We can still investigate this, but maybe separately.

Updating macos now (for completely other reasons) so can't test anything right now.

@brandon.ringe what clojure-lsp version Calva master is using?

Yes, the PR seems fine otherwise.

03.01.19

@pez you mean 2021.02.10-03.01.19 ?

Yes

I see, there was some fixes and features on some releases after that, @brandon.ringe maybe we should try to investigate those issues to bump Calva to latest clojure-lsp

@brandon.ringe maybe the problems that @leoiacovini is experiencing are not due to clojure-lsp version?

Yeah, it seems so. In any case I just set the version back to 2021.02.10-03.01.19 in the PR, so at least we can isolate issues better.

@ericdallo We'll definitely want to work out those issues with later versions, but after the PR is merged would be better, I think.

Sure!