Fork me on GitHub
#lsp
<
2022-04-04
>
snoe06:04:48

Anyone else seeing completions come in really slow? I'm on a relatively small project and they seem to be taking about 1s. What this means is that when the lsp completions come in, they replace the buffer completions. So if I have a buffer completion selected and they get replaced as I hit enter, I end up getting a newline munged into the buffer. Super annoying to be hitting this third case all night. Here's three attempts (sorry low framerate) where I do the same key combinations. First one I waited for lsp to come in before enter. Second one I selected and hit enter before lsp came in. Third one I selected before and hit enter after.

snoe06:04:14

Not sure how to help this, except by making completions as fast as possible

ericdallo11:04:43

The newline is pretty odd, seems like a client issue

ericdallo11:04:47

About the server performance, it should not be slow, we improved performance recently on that, maybe we Introduced a new issue? c/c @U07M2C8TT

ericdallo12:04:06

@U0BUV7XSA curious, how much time completion and how many elements are coming? we have this answer on server logs included recently

snoe14:04:20

@UKFSJSM38 yeah the client is getting confused because the lsp completion is so slow. it's taking about 700ms for 3-50 completions pretty consistently. definitely feels like a regression (this is on master).

ericdallo14:04:34

yes, sounds like a regression, I think I noticed some performance issues on completion last week and didn't give the proper attention thinking it was something with my config, good to confirm that.

ericdallo14:04:53

It may be related with some change on queries / completion we did recently @U07M2C8TT

jacob.maine17:04:28

Not much has changed in completions lately. We switched to the q/filter-project-analysis-xf transducer a few days ago. About a month back we added the practicalli snippets. I don’t see much else that’s different. I’ll plan to hook up the flamegraphs and see if I can track anything down.

snoe17:04:07

curious @UKFSJSM38, how does lsp-mode handle late completions? If you put a 2s sleep in the completion handler, what happens if you have a completion item selected when they show up? @U07M2C8TT That was the first handler I wrote, looking at the code and there's gotta be redundancies in there. I'll bet we're iterating through analysis 3-4 times.

ericdallo17:04:03

@U0BUV7XSA lsp-mode only show the completion popup when server returns

snoe17:04:21

oh, so you don't see other sources?

ericdallo17:04:03

I don't think so

1
jacob.maine17:04:01

I think it depends a lot on how you have completions configured. That suggests that there’s a nice way to configure completions, which is completely false. Completion configuration in Emacs is a disaster, IMO. In my—admittedly probably broken—configuration the editor and clojure-lsp compete for who gets to manage the completions. I still haven’t really figured out when one takes priority. @UKFSJSM38 helped me figure out a hack that prevents CIDER from stealing the completion priority when you start a REPL, but that was also a pain point for me for a long time.

ericdallo17:04:01

yeah, emacs completion package (company) has the concept of backends (and frontends, but not relevant for now), so one could have a lsp-backend snippets-backend which would bring both completion items, but I'm not sure what happens when one takes more time than other, if company just wait all backends provide items

ericdallo17:04:34

that means, it's possible to have both cider and clojure-lsp completions teorically, but that would probably cause lots of duplications and performance issues

jacob.maine17:04:06

> I’ll bet we’re iterating through analysis 3-4 times At one point we were iterating hundreds of times, although that was fixed in https://github.com/clojure-lsp/clojure-lsp/pull/764 It looks like you’re in a CLJS project @U0BUV7XSA, which has to return both clojure.core and cljs.core completions, both of which involve an expensive iteration. Out of curiosity, is this problem worse in CLJS projects?

☝️ 1
jacob.maine18:04:29

Oh, another question @U0BUV7XSA… does your completion start after 1 character? Or worse, 0 characters? I made a series of PRs that speeds up clojure.core completion when there are lots of matches, but it can still be slow.

ericdallo18:04:13

yeah, for emacs/lsp-mode 2 chars it's the recommended for best performance/UX tradeoff

jacob.maine18:04:40

(0 characters would be completion from a blank line or something like that. You’d notice log lines with huge numbers of items :completion 1000ms - total items: 899 )

snoe18:04:49

Yup, that was a cljs project, in a .cljs file. Getting 300-1500ms in clojure-lsp, even at 5 chars. Seems like 400ms standard.

snoe18:04:41

in the cljs project, 700-800ms seems to be consistent

snoe18:04:53

-------------------------------------------------------------------------------
Language                     files          blank        comment           code
-------------------------------------------------------------------------------
ClojureScript                    8            129              3           1143
ClojureC                         3             45              0            411
Clojure                          3             33              0            227
-------------------------------------------------------------------------------
SUM:                            14            207              3           1781
-------------------------------------------------------------------------------
but npm react deps.

jacob.maine18:04:55

Hmm, not really that big of a project

jacob.maine18:04:08

(What LOC tool do you use?)

jacob.maine18:04:37

@UKFSJSM38 do you remember how to change the number of characters you need to type before completion starts in Emacs?

ericdallo18:04:49

yes: (setq company-minimum-prefix-length 2)

jacob.maine19:04:27

@U0BUV7XSA I’m having trouble reproducing times that long. I have a CLJS project of a similar size (1900 lines). I’ve adjusted completion to start after 1 character. For me, completion is generally in the 200-300ms range, occasionally getting up toward 400ms. Still not immediate, but closer to what I recall the performance being.

jacob.maine19:04:58

Will you paste your server-info?

jacob.maine19:04:35

@UKFSJSM38 I’m noticing that both :classpath and :settings :source-paths contain duplicates. I’m not sure that’s related to this problem, but it can’t be good for performance

ericdallo19:04:14

hum, not aware of that, could you paste a example?

ericdallo19:04:25

Odd, I see only the src twice, we should save that as a set or fix the duplication

jacob.maine19:04:41

Yes, src twice in :source-paths, but many other things are duplicated in :classpath —for example cemerick/url. Both of them should be sets

ericdallo19:04:06

Oh that's pretty bad and should be fixed, yeah, making a set would easily solve that but I wonder why that is happening

snoe19:04:23

here's all my dep setup and server info. Something I realized is by having shadow handle one classpath and lein the other, the dep trees will have conflicting versions when we mash them together (see slf4j-api) https://gist.github.com/snoe/3375ccc12bf28f366f0a6b01b6ed022d

snoe19:04:49

I also see the same version of medley due to this mashing.

ericdallo19:04:13

Yeah that's badd too @U0BUV7XSA 😂 not sure how to solve that, maybe consider only the most recent?

snoe19:04:30

Probably

snoe19:04:06

Or rather I think there's stuff in java to take a classpath and produce a package list perhaps. only the first package wins in classpath order

jacob.maine19:04:15

The :classpath also often has duplicates because of relative paths: /Users/case/dev/secret/cross/src and cross/src . Is that expected @UKFSJSM38?

jacob.maine19:04:14

Same problem with relative paths in :source-paths too, actually

jacob.maine19:04:16

I have a theory for why I see duplicate :source-paths in my CLJS project. I have a deps.edn file, with :path ["src"]. I also have a shadow-cljs.edn file, with :deps true, which in shadow terms means “load deps from deps.edn”. So, when we ask both dependency managers for paths, they both include "src" .

ericdallo20:04:57

the :source-paths should be always absolute, I thought we did that somewhere

ericdallo20:04:29

but yeah, I think lein returns relative and deps.edn absolute or something like that, we should always "absolutize" so we can set safely

ericdallo20:04:04

BTW, almost sure we set that somewhere before sending to kondo, but probably we should do it earlier right after getting the classpath/source-paths

snoe20:04:50

@U07M2C8TT is the code to produce the flame graph still there? I'm curious to see on this project.

ericdallo20:04:54

yeah, there is a commit/branch somewhere that @U07M2C8TT linked it in a recent PR

snoe20:04:34

https://github.com/ptaoussanis/tufte is what I used when building out the parser. It was nice to see only the call times I was interested in

jacob.maine20:04:05

@U0BUV7XSA there are some instructions for getting a profiling build here https://clojure-lsp.io/development/#profiling. I’ll dig up one of the commits @UKFSJSM38 mentioned

👍 1
jacob.maine20:04:17

@U0BUV7XSA the first commit in https://github.com/clojure-lsp/clojure-lsp/pull/795/commits includes code for constructing flamegraphs

jacob.maine20:04:07

Since I can’t reproduce the poor performance you’re seeing, I was going to suggest that we get your environment set up to do some profiling. Let me know how I can help. I can jump on a call if that’s easiest

snoe21:04:41

@U07M2C8TT here's the flamegraph, I kinda hate sampling profilers, so maybe you can get better insight than I. The first is a single run of a completion, the second is dotimes [n 100] of the same call. You can see times are consistently 700ms. What is a typical time for a completion for you in the clojure-lsp project?

snoe21:04:45

For context: Originally, completion ran synchronously as you typed, and I know that at one point I had it down below 30ms on this machine with a project with 10x the deps.

snoe21:04:19

before graal/kondo

jacob.maine21:04:32

Ah, those flamgraphs are very interesting… jar-file? shows up three different times and accounts for about 50% of the time. That’s new code. Looks like maybe an inefficient regex. Could that function just be (string/includes? % ".jar") @UKFSJSM38?

jacob.maine21:04:18

Completion is taking 200-400ms for me at the moment in clojure-lsp, with completion starting after 1 character

jacob.maine21:04:21

We have some work to do before we’re back down to the tens of milliseconds. It’s not impossible but it’ll take some work

ericdallo21:04:11

> That’s new code. Looks like maybe an inefficient regex. Could that function just be (string/includes? % ".jar") @UKFSJSM38? Yep, probably that's the culprit :)

ericdallo21:04:41

yeah, IMO completion is more consistent than before but slower indeed probably related with the analysis iteration. For now I'll improve the jar-file? fixing that specific issue

👍 1
jacob.maine21:04:10

@UKFSJSM38 class-file? could also be a string/ends-with? . That wouldn’t speed up completion, but might be worth changing at the same time.

ericdallo21:04:23

that reminds me that is pretty hard to make some code that could not side effect other features, we should try in the future to have performance tests just like kondo has

ericdallo21:04:16

yes, I was not aware those functions could casue that slowness, will do some checking on all of them profiling it and let you know

jacob.maine21:04:23

> we should try in the future to have performance tests Yeah, good idea. Want to start an Issue where we can discuss that?

ericdallo21:04:33

yep, feel free to create one regarding that

ericdallo21:04:54

BTW, I think we will have to use includes? instead of ends-with? as we can have cases like: /foo/bar.jar!/baz.clj

jacob.maine21:04:14

Yeah, I was expecting includes? for jar-file?, and ends-with? for class-file?

👍 1
snoe22:04:42

Tried something naive for jar-file?

(def ^:private jar-file-with-filename-regex-fast #"\.jar:.*")
(defn jar-file? [filename]
  (or (boolean (re-find jar-file-with-filename-regex-fast filename))
      (boolean (string/ends-with? filename ".jar")))) 
Still at 500ms here's 10 executions.

snoe22:04:14

(defn jar-file? [^String filename]
  (or (boolean (.contains filename ".jar:"))
      (boolean (string/ends-with? filename ".jar"))))
seems fast ~400ms

snoe23:04:31

Changing with-core-items to not call var-defs-in-ns-named cuts time to ~200ms - it's just used for :kind so that should be hardcoded into common-sym

ericdallo23:04:10

Yeah, sounds like a valid improvement

snoe23:04:09

in completion, we make external-ns-elements and other-ns-elements and then immediately (concat external-ns-elements other-ns-elements) and do nothing else with them. I believe the concats are probably a mistake (we don't want other project's aliases), but as it stands all that code can be simplified to all-other-analysis (mapcat val (dissoc analysis filename))

👍 1
snoe23:04:48

that takes it down to ~60ms

ericdallo23:04:38

@U0BUV7XSA thanks, I'll take a look and check if those improvements are valid, it probably is, just to make sure we are not missing anything

snoe23:04:19

thanks @UKFSJSM38 ya, I probably won't have time to make the pr, just putting it here to look into.

ericdallo00:04:50

Np, that is already really valuable info

jacob.maine06:04:33

Those are great observations @U0BUV7XSA. I didn’t realize that the only benefit of looking up all those clojure.core items was getting :kind. If that can be hard-coded, that trims off a huge amount of time. I agree that we don’t need external aliases but we might want external keywords, for libs that export specs or re-frame events, right? If we do, I’d accept using the full analysis—and getting unwanted aliases—just to get better performance. Several days ago @UKFSJSM38 was seeing the filters for internal/external filenames take upwards of 100ms, even before this performance regression. In the long run, we need to be able to separate internal and external files quickly, as well as pick out files that modify particular namespaces. We’ve been talking about keeping a cache of file metadata for this case among others. Any thoughts on that?

snoe07:04:06

Hrm, so, in that project there's 40k files in (keys analysis) . 18k .java & 21k .class. Seems kinda crazy to be the java stuff in the same analysis to me. But this shows that external can be 2-4 order of magnitude bigger than project (even without the java deps, so many projects just balloon like this). So I agree it's necessary to separate the two (I'd argue this shows java stuff is a third). However, I think this clearly shows that walking through external is expensive. So external keywords and stuff, should probably be an opt in setting if they can't be narrowed down to a particular file based on the cursor-value. I can't think why they can't follow the same rules as we do for namespace functions: if the alias/ns is a perfect match show all the functions. Caches for external stuff makes sense to me, if the deps change clear and recalc once. For project stuff I think it's real tricky and should be avoided beyond "these files are in the project" or "this is a separate project analysis". I used to analyze source-paths separately from classpath for this reason.

ericdallo12:04:53

we still analyze source-paths separately from classpath, and I agree if we would have a cache for project analysis the consistency needs to be perfect, I think starting with external deps is a huge step and if it works well we can think about how that would work for project in the future. But basically the naive idea is: if my cache says file /a.clj has SHA 123, and analysis {...}, next time, if sha matches I don't want to analyze that again, unless kondo config/version changed and etc, needs some research yet tho

ericdallo15:04:28

> in completion, we make external-ns-elements and other-ns-elements and then immediately (concat external-ns-elements other-ns-elements) and do nothing else with them. I believe the concats are probably a mistake (we don't want other project's aliases), but as it stands all that code can be simplified to all-other-analysis (mapcat val (dissoc analysis filename)) You are right, that's probably a regression related to the multiple refactors that function already received 😅 I'm working on the completion improvements discussed here, and managed to make take ~120ms with a empty completion with >1000 items 😄 It's really notable the improement on the editor

ericdallo15:04:06

https://github.com/clojure-lsp/clojure-lsp/commit/cd3300e93349dabe3689815df5107c7aafbd8b38 improves the performance, but it may be a good idea @U0BUV7XSA test in that huge project of yours. Testing on clojure-lsp, I noticed the perofmrnace improvent was from 199ms -&gt; 110ms, but probably before the change huge projects with a lot of analysis should grow exponentially that number

jacob.maine16:04:39

ooh… I’m excited to try this @UKFSJSM38. I was also noticing that some vars were added in Clojure 1.10 and 1.11 that haven’t made it into clojure-lsp. Some of them are new and some of them have moved from cljs to clj. Are you already working on adding those? If not, I can take that

ericdallo16:04:40

nope, I noticed the same, but didn't touch yet, we should add missing ones like update-val etc indeed

jacob.maine17:04:11

With that patch, completion is consistently in the 100-200ms range for me. Awesome!

🚀 1
snoe18:04:42

I'm down to 150 - 250ms - the late pop-in virtually gone so this a great step.

ericdallo18:04:31

Great, we can probably focus on minor improvements now as I don't think/didn't easily found some code that takes most of the time, a flamegraph profiler would help with that probably

snoe18:04:44

@U07M2C8TT thanks for the debug-perf-cli build, I wonder if there's a reason to keep it separate from debug. I also think it might be nice to have a ./dev/clojure-lsp/debug.clj file with snippets and instructions to run a profile or a criterium.

ericdallo18:04:57

Yeah, both ideas sounds good to me, usually there are user.clj namespaces on lein projects, maybe we could have a performance one or something

jacob.maine18:04:05

Yeah, agreed. @UKFSJSM38 I think you suggested merging the perf deps into the main debug build when I first proposed it. I can’t remember why I was hesitant then. In retrospect, it doesn’t seem like it would hurt

👍 1
rayat15:04:06

How do i solve this but for cljs and npm modules? https://clojurians.slack.com/archives/CPABC1H61/p1648498183242179?thread_ts=1648497689.774539&amp;cid=CPABC1H61 > (IDK if it matters but I'd like to have this for shadowcljs and calva)

ericdallo15:04:00

what exactly? find definition for npm you mean?

ericdallo15:04:53

that is not supported yet along with java completion. we intend to add that soon on clj-kondo so we can make clojure-lsp work

pez16:04:38

Calva does JS completions when the REPL is connected. Not working for you, @U037TPXKBGS?

rayat16:04:08

@UKFSJSM38 yeah, for installed and required/imported npm modules/packages. And yeah that makes sense! @U0ETXRFEW For arbitrary third party npm libraries? I've seen it for standard js stuff like console log and such so far, but not third party ones. Function parameter help would be nice too!

ericdallo16:04:50

yeah, that is something cool we would like to add in the future

❤️ 1
pez17:04:16

Like so for a require like

(:require ["@snowplow/browser-plugin-link-click-tracking" :as link-tracking]
            ["@snowplow/browser-tracker" :as sbt]

pez17:04:14

Not sure where the limits go for this approach, but the project to contribute to for improving it is: https://github.com/clojure-emacs/clj-suitable

1
rayat18:04:55

Huh, i don't think i get that consistently. It is complicated because our work codebase is a big monorepo so calvas single repl limitation plus my frequently working across the monorepo might affect that