RomeuG
commented
3 years ago Sorry, the title is kind of wrong. It should be: Emacs hangs temporarily while trying to get completion while rust-analyzer is initializing.
Closed RomeuG closed 3 years ago
RomeuG
commented
3 years ago Sorry, the title is kind of wrong. It should be: Emacs hangs temporarily while trying to get completion while rust-analyzer is initializing.
yyoncho
commented
3 years ago Hanging might be caused by establishing the watches which happens during startup and causes hanging. Can you provide perf report?
RomeuG
commented
3 years ago This is the perf report:
168 66% - ...
167 66% - company--perform
167 66% - company--begin-new
167 66% - company-calculate-candidates
167 66% - company--fetch-candidates
167 66% - company-call-backend-raw
167 66% - apply
167 66% - company-capf
167 66% - company-capf--candidates
167 66% - completion-all-completions
167 66% - completion--nth-completion
167 66% - completion--some
167 66% - #<compiled 0x11b93509fa5b617b>
165 65% - completion-basic-all-completions
165 65% - completion-pcm--all-completions
165 65% - #<compiled -0x1c081f0461c2fb95>
165 65% - #<compiled -0x1a98156bc45cc026>
13 5% - lsp-request-while-no-input
12 4% + #<compiled -0x10d7bc3be3860626>
1 0% - lsp-completion--filter-candidates
1 0% + -keep
1 0% + completion-pcm-all-completions
1 0% + completion-emacs22-all-completions
1 0% + ivy-thing-at-point
0 0% Automatic GC
55 21% + command-execute
13 5% + company-post-command
11 4% + timer-event-handler
3 1% + redisplay_internal (C function)
1 0% #<compiled -0x10d7bc3be3860626>Doesn't seem to be the watches stuff. Even if it was, shouldn't it be async, though?
RomeuG
commented
3 years ago The completion itself is slow while typing too. Although thats because of the rust-analyzer server.
But VSCode handles it asynchronously (doesn't hang while typing).
kiennq
commented
3 years ago The lsp-request-while-no-input only takes 5%, so it's not likely cause the hang.
What's your Emacs version? Can you try to eval-defun for lsp-completion-at-point and try to post the perf log again?
RomeuG
commented
3 years ago @kiennq
I am using GNU Emacs 28.0.50. I am also using the native-comp branch.
This also happens on Emacs version 27.1. But it seems the perf log has different results (sorry for the format):
- ... 234 80%
- company--begin-new 234 80%
- company-calculate-candidates 234 80%
- company--fetch-candidates 234 80%
- company-call-backend-raw 234 80%
- apply 234 80%
- company-capf 234 80%
- company-capf--candidates 234 80%
- completion-all-completions 234 80%
- completion--nth-completion 234 80%
- completion--some 234 80%
- #<compiled 0x15819630a719> 234 80%
- completion-basic-all-completions 234 80%
- completion-pcm--all-completions 234 80%
- all-completions 234 80%
- #<compiled 0x15819630a69d> 234 80%
- #<compiled 0x15819630a681> 234 80%
- lsp-request-while-no-input 226 77%
- accept-process-output 9 3%
- #<compiled 0x1581958c2799> 9 3%
- lsp--parser-on-message 3 1%
- lsp--on-notification 2 0%
+ #<compiled 0x15819579bd59> 1 0%
+ lsp--get-message-type 1 0%
- mapcar 1 0%
+ lsp--parse-header 1 0%
Automatic GC 0 0%
+ command-execute 41 14%
+ company-post-command 5 1%
+ redisplay_internal (C function) 4 1%
+ #<compiled 0x1581958c2799> 4 1%
+ timer-event-handler 4 1%It seems now lsp-request-while-no-input takes most of the time. Emacs hanged for 5 seconds, more or less.
If I run eval and use (lsp-completion-at-point), it is basically instant. (I hope this is what you asked)
kiennq
commented
3 years ago If I run eval and use (lsp-completion-at-point), it is basically instant. (I hope this is what you asked)
Well, what's I'm hoping is more information than just #<compiled ...> showing up. To do that we will need to reevaluate the functions again without let it byte-compiling, then do the repro steps again.
Can you try to go to lsp-mode.el and lsp-completion.el, run M-x eval-buffer in each file, try to repro the hang again and post the perf here?
RomeuG
commented
3 years ago @kiennq
Hey, thank you for helping me help you debug this problem. Here are the results after doing what you said:
153 74% - ...
153 74% - completion-basic-all-completions
153 74% - completion-pcm--all-completions
153 74% - #<lambda 0x15fc25c9f652ea8f>
153 74% - cond
153 74% - funcall
153 74% - #<lambda 0x1313c1e802e4f86e>
153 74% - let
153 74% - catch
153 74% - let
153 74% - cond
153 74% - let*
150 72% - lsp-request-while-no-input
150 72% - let*
150 72% - unwind-protect
150 72% - progn
148 71% - while
12 5% - accept-process-output
12 5% + #<lambda -0x15bcf0911b730f27>
5 2% - not
3 1% or
2 0% + let*
3 1% + progn
0 0% Automatic GC
36 17% + command-execute
11 5% + company-post-command
3 1% + timer-event-handler
2 0% + redisplay_internal (C function)
1 0% + #<lambda -0x15bcf0911b730f27>It seems it wastes most of the time in a while loop:
(cl-defun lsp-request-while-no-input (method params)
"Send request METHOD with PARAMS and waits until there is no input.
Return same value as `lsp--while-no-input' and respecting `non-essential'."
(let* (resp-result resp-error done?)
(unwind-protect
(progn
(lsp-request-async method
params
(lambda (res) (setf resp-result (or res :finished)))
:error-handler (lambda (err) (setf resp-error err))
:mode 'detached
:cancel-token :sync-request)
(while (not (or resp-error resp-result
(and non-essential (input-pending-p))))
(accept-process-output nil 0.001))
(setq done? t)
(cond
((eq resp-result :finished) nil)
(resp-result resp-result)
((lsp-json-error? resp-error) (error (lsp:json-error-message resp-error)))
((input-pending-p) (when lsp--throw-on-input
(throw 'input :interrupted)))
(t (error (lsp:json-error-message (cl-first resp-error))))))
(unless done?
(lsp-cancel-request-by-token :sync-request)))))(while (not (or resp-error resp-result
(and non-essential (input-pending-p))))
(accept-process-output nil 0.001))
aaronjensen
commented
3 years ago In general, it's been my experience that since moving away from company-lsp (which was an async company backend) that company-capf is pretty much unusable with a low company-idle-delay. A return to company-lsp would be welcome, though maybe this inquiry will lead somewhere...
RomeuG
commented
3 years ago I totally agree with you. I don't remember having these kinds of issues with company-lsp.
yyoncho
commented
3 years ago The only way company-capf to block if you somehow force non-essential call, my personal opinion is that we should never block.
By default, company-capf does not block.
aaronjensen
commented
3 years ago Sorry to disagree, but in practice that's just not the case. In typescript projects typing stutters all the time with an idle delay of 0.125. When I disable company it goes away. When I replace it with company-lsp and add stubs for the now missing functions, it goes away.
yyoncho
commented
3 years ago @aaronjensen do you see it with lsp-start-plain.el? If yes, can you provide a project to reproduce the issue with? I think that at some point doom had issues related to forcing non-essential calls.
yyoncho
commented
3 years ago @aaronjensen can you test after removing the non-essential, like this:
(cl-defun lsp-request-while-no-input (method params)
"Send request METHOD with PARAMS and waits until there is no input.
Return same value as `lsp--while-no-input' and respecting `non-essential'."
(let* (resp-result resp-error done?)
(unwind-protect
(progn
(lsp-request-async method
params
(lambda (res) (setf resp-result (or res :finished)))
:error-handler (lambda (err) (setf resp-error err))
:mode 'detached
:cancel-token :sync-request)
(while (not (or resp-error resp-result
(and (input-pending-p))))
(accept-process-output nil 0.001))
(setq done? t)
(cond
((eq resp-result :finished) nil)
(resp-result resp-result)
((lsp-json-error? resp-error) (error (lsp:json-error-message resp-error)))
((input-pending-p) (when lsp--throw-on-input
(throw 'input :interrupted)))
(t (error (lsp:json-error-message (cl-first resp-error))))))
(unless done?
(lsp-cancel-request-by-token :sync-request)))))@yyoncho my problem appears to be garbage collecting. It seems that LSP auto complete, regardless of whether or not it's company-lsp or company-capf triggers garbage collecting every other character that's typed pretty much.
So, I was mistaken when I said it worked with company-lsp, I apologize for that.
One thing of note is that I too am on native-comp, so perhaps it has something to do with that?
@RomeuG if you try setting (setq gc-cons-threshold most-positive-fixnum), does perceived performance improve?
aaronjensen
commented
3 years ago Something looks very wrong. This is a memory profile. Typing about 8 characters led to 300MB of allocation?
305,357,575 98% - timer-event-handler
305,357,575 98% - apply
305,317,487 98% - company-idle-begin
300,309,882 96% - company-auto-begin
300,309,882 96% - company--perform
300,309,882 96% - company--begin-new
300,252,930 96% - company-calculate-candidates
300,239,238 96% - company--fetch-candidates
300,239,238 96% - company-call-backend-raw
300,239,238 96% - apply
300,239,238 96% - company-capf
300,239,238 96% - company-capf--candidates
300,239,238 96% - completion-all-completions
300,239,238 96% - completion--nth-completion
300,239,238 96% - completion--some
300,239,238 96% - #<compiled -0x74f3aa7d67826e2>
300,040,086 96% - completion-basic-all-completions
300,040,086 96% - completion-pcm--all-completions
300,039,062 96% - #<lambda -0x628160d5b0eba8a>
300,039,062 96% - cond
300,039,062 96% - funcall
300,039,062 96% - #<lambda -0xb1b3cf7f5c39fe8>
300,039,062 96% - let
300,039,062 96% - catch
300,039,062 96% - let
300,039,062 96% - cond
300,033,154 96% - let*
300,009,662 96% - lsp-request-while-no-input
299,980,654 96% - let*
299,980,654 96% - unwind-protect
299,980,654 96% - progn
299,949,194 96% - while
127,830,914 41% - accept-process-output
127,830,914 41% - #<lambda 0xedc1b7bb7a5c80c>
85,408,840 27% - while
85,408,840 27% - if
85,408,840 27% - let*
85,401,672 27% + if
7,168 0% + and
42,422,074 13% + setq@aaronjensen I don't think you should set the gc-cons-threshold to very high value. Depends on language server, the json message passing around can be huge and it can quickly reach very high memory usage. Which in turn will freeze Emacs forever for garbage collecting.
I'm setting (setq gc-cons-threshold #x8000000) and pretty comfy with that.
Can you try with https://github.com/emacs-lsp/lsp-mode/pull/2176 and take the profiling again?
The accept-process-output can be anything, even reacting to response from other request, not necessarily because of completion. This commit is separating that.
yyoncho
commented
3 years ago Also, can you include memory profile?
Edit: ignore, previous profile was memory profile.
aaronjensen
commented
3 years ago @kiennq I know I shouldn't, I only mentioned that as an experiment. I'm currently trying out 1GB along w/ gcmh which will GC on idle. This at least allows me to type without constant stutters.
Here's the memory profile with that patch:
And here's a profile on Emacs 28 master w/o native-comp (also with that patch). I typed more on the above profile, which is probably why the memory usage is higher.
kiennq
commented
3 years ago Can you also post cpu profile too?
yyoncho
commented
3 years ago @aaronjensen is this a public project?
yyoncho
commented
3 years ago @aaronjensen is this a public project?
I was able to reproduce the issue - I will investigate where the issue comes from.
yyoncho
commented
3 years ago I am receiving 1500 $progress notifications when performing 1 completion...
RomeuG
commented
3 years ago @aaronjensen
It definitely improves. I still did notice some hiccups here and there, but not as bad like before.
yyoncho
commented
3 years ago aaronjensen
commented
3 years ago That did not appear to change anything for me.
aaronjensen
commented
3 years ago One oddity... Looking at the lsp-io logs, I see that when the completion info comes back for me typing "Re" it includes essentially the entire dictionary of top level symbols. Furthermore, because I have date-fns as a dependency and the way that TypeScript appears to resolve autocompletes, it includes each function multiple times.
Furthermore, it appears to send responses even for canceled requests, though I don't know if lsp is parsing them.
Essentially, a tremendous amount of traffic is being generated. I imagine all of that is turned into Lisp strings and parsed, which creates a ton of objects to GC.
yyoncho
commented
3 years ago That did not appear to change anything for me.
the comment was for rust-analyzer issues. Is your project public? We need to measure the size of the ts-ls response. if it is too much, the only option seems to be to ask the server devs to start returning partial results. As a side note, I believe that if you compile lsp-mode with lsp-use-plists = t, the gc pressure will be decreased.
aaronjensen
commented
3 years ago No, the project is not public, but this minimal react app reproduces it: https://github.com/aaronjensen/lsp-completion-repro
Run npm install or yarn install to install packages
Set company-idle-delay to 0
You can also set company-minimum-prefix-length to 1
Open App.tsx
Above the App declaration, type Rea
It doesn't grow as quickly as our app does because our app has more dependencies and more top level declarations, but this gives you an idea.
Should lsp-mode be caching these results at all? It seems like the completion results are identical regardless of what I type.
Either that, or can ts-ls be convinced to filter the results based on the prefix?
yyoncho
commented
3 years ago Should lsp-mode be caching these results at all?
Results are context-dependent
Either that, or can ts-ls be convinced to filter the results based on the prefix?
Other servers tend to filter top-level results and return partial results which involve server-side filtering.
aaronjensen
commented
3 years ago I did some testing in VS Code and it seems like they get the same results (that is, every single possible completion assuming no prefix). They do not, however, re-request completion when the prefix changes. If you go somewhere else in the file and start typing there, it re-requests.
Results are context-dependent
Understood, though for top level variables, that context with ts-ls is the global context and that's the same regardless of what you type. They do not filter, so the filtering must be done on the client side and lsp-mode should not re-request completions for every character typed. This works as expected if you wait long enough for the results to come back and be parsed. If, however, typing interrupts lsp's capf, it cancels the request and starts again. Because the response still comes back, you get flooded with request.
Ideally, lsp would not cancel the request when typing interrupts (just cancel waiting for it) and still allow caching its result. I'm not sure exactly how that would work, but it does appear that the problem is completions getting triggered that do not complete building up.
aaronjensen
commented
3 years ago Oh, and I tested lsp-use-plists t and it still ate memory quickly, but I can't say whether or not it slightly decreased memory usage.
yyoncho
commented
3 years ago Ideally, lsp would not cancel the request when typing interrupts (just cancel waiting for it) and still allow caching its result. I'm not sure exactly how that would work, but it does appear that the problem is completions getting triggered that do not complete building up.
We cannot do that because we don't know if the initial request was partial or not.
aaronjensen
commented
3 years ago we don't know if the initial request was partial or not
What do you mean by partial?
kiennq
commented
3 years ago Can you take an io trace when typing? lsp-mode should do the cache automatically if the server is saying it has sent all data.
Also can you check the value of your lsp-completion-no-cache?
yyoncho
commented
3 years ago we don't know if the initial request was partial or not
What do you mean by partial?
The initial result might be partial and not containing all of the result items, thus we have to make another request. If we wait for the first result without making a second we will have to make another call but with a redundant delay.
I am testing with your project, and I don't see any huge delay also the responses are pretty small, ~1mb. Can you eval the following:
(defun lsp--get-body-length (headers)
(let ((content-length (cdr (assoc "Content-Length" headers))))
(if content-length
(progn
(message "%s >>> " content-length)
(string-to-number content-length))
;; This usually means either the server or our parser is
;; screwed up with a previous Content-Length
(error "No Content-Length header"))))
This will give us an idea of how big are the responses?
yyoncho
commented
3 years ago Can you take an io trace when typing?
lsp-modeshould do the cache automatically if the server is saying it has sent all data. Also can you check the value of yourlsp-completion-no-cache?
@kiennq the issue is that the server was unable to respond in time, and we make a second request then we receive the first response and we have to parse it because there is no way to know that the request is canceled.
aaronjensen
commented
3 years ago lsp--get-body-length
346 >>> [2 times]
401 >>>
1122241 >>>
346 >>>
571645 >>>
297748 >>>
230289 >>>
215595 >>>
214210 >>>
346 >>>
508 >>> That's evalling, then holding R until it typed 6 times.
I have no idea why memory usage is growing so quickly compared to the payload sizes.
yyoncho
commented
3 years ago what is your gc-cons-threshold? These values are not that big.
aaronjensen
commented
3 years ago When this started it was 16MB. But as the memory profile shows, memory allocation grows to 100s of MB after typing just a few characters. Furthermore, a GC is triggered almost every other character typed. The payload sizes aren't massive, but something is causing them to allocate 100s of MB.
yyoncho
commented
3 years ago I tested with emacs 28 from yesterday with native comp and also with emacs 27.1, using the config from https://emacs-lsp.github.io/lsp-mode/tutorials/reactjs-tutorial/ and I didn't saw any gc spikes. Can you try to collect memory allocation from that scenario(holding 6 times R) so I can try to compare it with the one on my side.
aaronjensen
commented
3 years ago This is with my config.
Unfortunately I'm not able to get the tutorial configuration working right away due to path/node installation issues.
For your test, please make sure you have company-mode enabled and:
(setq company-minimum-prefix-length 1
company-idle-delay 0)Also, that config defaults to gc cons threshold of 100MB, which may be enough to prevent stutters when typing normally in this scenario.
Here's the profile from the config you linked to:
yyoncho
commented
3 years ago @aaronjensen I can confirm that memory generation is similar but with 100mb GC cons threshold I don't see big lags. I will do some investigation to see if we can reduce the memory footprint. We soon switch to plists as well.
yyoncho
commented
3 years ago @aaronjensen which is your emacs 28 commit? It might be GC perf regression.
aaronjensen
commented
3 years ago Is there a known regression? I don’t have the commit handy but it’s within the last month.
GC only takes about 250ms but that’s super noticeable when typing and combined with the 60ms parse time(s).
I’m using 1gb gc cons threshold for now and I’ll see how that goes, but yeah improvements to memory consumption would be great.
yyoncho
commented
3 years ago @aaronjensen I am working on this, there is POC at https://github.com/yyoncho/lsp-mode/tree/perf
aaronjensen
commented
3 years ago That's great, thank you. Let me know when you have something you'd like me to test and I'd be happy to.
yyoncho
commented
3 years ago @aaronjensen you may try that perf branch with lsp-use-plists = t.(ignore the memory reports because although they report more memory usage it does not go to GC).
yyoncho
commented
3 years ago @aaronjensen as a side note - this might be related to the perceived lag - https://github.com/emacs-lsp/lsp-mode/issues/2758#issuecomment-817258467
The issue is that typing looks laggy but in fact, it is not actual lag but missing redisplay call and the ui does not represent the actual state.
Describe the bug Emacs hangs temporarily while trying to get completion while
rust-analyzeris initializing.rust-analyzertakes some seconds to initialize, going from a small amount of RAM to 900MB RAM (this is normal, just giving away some details).To Reproduce Steps to reproduce the behavior(sample project + file which can be used to reproduce the issue with.)
Expected behavior Emacs should not hang temporarily.
Which Language Server did you use I used
lsp-rustwithrust-analyzer.OS GNU/Linux
Error callstack Information from
*lsp-log*: