Fork me on GitHub
#lsp
<
2022-04-14
>
djm07:04:29

I’ve just upgraded to clojure-lsp 2022.03.31-20.00.20 (nix on macos (intel)) and now it’s using ~100% CPU all the time. I’ve seen the same issue with 3 different lein projects. 1) Has anyone else seen this, 2) What can I do to debug it?

djm07:04:52

lsp-doctor says

Checking for Native JSON support: OK
Check emacs supports `read-process-output-max': OK
Check `read-process-output-max' default has been changed from 4k: OK
Byte compiled against Native JSON (recompile lsp-mode if failing when Native JSON available): OK
`gc-cons-threshold' increased?: OK
Using `plist' for deserialized objects? (refer to ): OPTIONAL
Using emacs 28+ with native compilation?: OK

lassemaatta08:04:57

does this happen with trivially small projects too, e.g. something like lein new app foo? With some of the larger projects I work with I've noticed that :refreshing-test-tree can take a while (5+ minutes of 100% cpu usage for a single core).

djm08:04:28

It doesn’t happen with a trivial project, but it does happen with a tiny project (~5 small namespaces)

djm08:04:03

The only interesting thing I can see in the logs is this:

2022-04-14T07:28:26.274Z  ERROR [taoensso.timbre:828] - Uncaught exception on thread: async-dispatch-4
com.oracle.svm.core.posix.thread.PosixJavaThreads.pthreadStartRoutine    PosixJavaThreads.java:  194
            com.oracle.svm.core.thread.JavaThreads.threadStartRoutine         JavaThreads.java:  597
                                                 java.lang.Thread.run              Thread.java:  829
                                                                  ...
   clojure.core.async.impl.concurrent/counted-thread-factory/reify/fn           concurrent.clj:   29
                   java.util.concurrent.ThreadPoolExecutor$Worker.run  ThreadPoolExecutor.java:  628
                    java.util.concurrent.ThreadPoolExecutor.runWorker  ThreadPoolExecutor.java: 1128
                                                                  ...
                                   clojure-lsp.handlers/initialize/fn             handlers.clj:  115
         clojure.core.async.impl.ioc-macros/run-state-machine-wrapped           ioc_macros.clj:  982
                 clojure.core.async.impl.ioc-macros/run-state-machine           ioc_macros.clj:  978
             clojure-lsp.handlers/initialize/fn/state-machine--auto--             handlers.clj:  115
          clojure-lsp.handlers/initialize/fn/state-machine--auto--/fn             handlers.clj:  116
    clojure-lsp.feature.java-interop/retrieve-jdk-source-and-analyze!         java_interop.clj:  182
                                                    babashka.fs/unzip                  fs.cljc:  887
                                             java.nio.file.Files.copy               Files.java: 3078
                                       java.io.InputStream.transferTo         InputStream.java:  704
                                    java.util.zip.ZipInputStream.read      ZipInputStream.java:  199
                                 java.util.zip.ZipInputStream.readEnd      ZipInputStream.java:  410
java.util.zip.ZipException: invalid entry CRC (expected 0xaec84e05 but got 0x3b81032f)

lassemaatta08:04:46

Looks a lot like the same issue I noticed a while back (https://clojurians.slack.com/archives/CPABC1H61/p1648893601867959), due to zlib 1.2.12. I don't think that caused any cpu usage increase.

borkdude08:04:02

I've seen that before. It's due to an issue with zlib. One should not use zlib 1.2.12 but 1.2.11 with Graal binaries

djm09:04:08

Okay, thank you. Is there a bug report for it anywhere?

lassemaatta09:04:57

I think there are a couple in the zlib repo, such as https://github.com/madler/zlib/issues/618. I don't think there's one for clojure-lsp.

thanks3 1
ericdallo11:04:20

About the test tree, I'm aware of that and we intend to do a fix soon. Also, next release will contain multiple improvements in CPU usage

ericdallo12:04:45

c/c @U07M2C8TT about test tree ☝️

jacob.maine12:04:56

I have a quick patch to test tree that reduces cpu usage. I'll try to submit that later today. I’m not certain it'll completely fix the problem but it'll make a dent

👍 1
lassemaatta12:04:18

feel free to ping me if/when you have a static binary available, I can run it on a couple of largeish projects and report back the logged durations 🙂

jacob.maine13:04:25

@U0178V2SLAY with the https://clojurians.slack.com/archives/CPABC1H61/p1650284730566659, will you check test tree duration at startup? I’d recommend restarting twice, the first time to build some new caches. You’ll want to wait until you stop seeing log entries for several seconds (or until CPU usage drops) before restarting.

lassemaatta14:04:38

@U07M2C8TT I did some comparisons with clojure-lsp 2022.03.31-20.00.20 and it looks like the cpu usage of :refreshing-test-tree has almost vanished.

🙏 1
ericdallo14:04:55

that's a huge improvement from the logs, awesome!

lassemaatta14:04:02

404999ms vs 336ms 😅

ericdallo14:04:07

For sure the jdk analysis cache are affecting on that too

ericdallo14:04:59

the time spent on refresh-test tree not necessary is related to that feature, clojure-lsp was running multiple async/go process at the same time, that's why a increased CPU and time

lassemaatta15:04:13

I saw a similar improvement with another project, where the duration went from 248551ms -> 615ms.

ericdallo15:04:24

the JDK cache + code performance improvement was a good combo to improve that

jacob.maine15:04:39

@U0178V2SLAY that’s great. I’ve been seeing similar improvements in other projects—refreshing the test trees doesn’t seem to contribute significantly to CPU time anymore. It looks like the time between starting lsp and when the clojure-lsp server is ready to start taking commands hasn’t changed much for you in this release (still 30-40s) but at least we’re not hogging your CPU for the next several minutes anymore.

ericdallo15:04:10

Yeah, @U07M2C8TT, his project is a good example on how caching project source not touched would improve startup, 28024ms for that project ATM

ericdallo15:04:31

I've seen few Nubank projects that take 1minute since they have lots of locs 😔

jacob.maine15:04:00

Yeah, I was noticing the same thing. Definitely a harder caching problem though

👍 1