Indentation very slow on 20230911.1653 about clojure-mode HOT 29 CLOSED

Also, a quick way to check if the new code is being used is M-: cider--sesman-friendly-session-calculated-at in the problematic buffer - it should have a non-nil value.

from clojure-mode.

The server is persistent.

from clojure-mode.

Thanks much for the report!

Will see if I can repro, if so I'll try to bisect its cause.

from clojure-mode.

I can't repro any sort of slowness - I can indent my whole ns buffer with clojure-mode in an instant.

Are you using something like electric-indent-mode, clojure-lsp, anything else that might query the indentation system?

from clojure-mode.

thanks for looking into this!

electric-indent, yes

from clojure-mode.

Nice.

IIRC you can (setq debug-on-quit t), C-g and see what clojure-mode was doing in a given moment?

If you do it enough times, you might perceive a common pattern.

from clojure-mode.

Here's a possible lead clojure-emacs/cider#3344

Apparently "electric / aggressive indentation modes" can query cider-current-repl which can be relatively slow, and noticeably slow if repeated enough times.

Would very much appreciate if you could verify a specific cause.

from clojure-mode.

Here's a benchmark you can run for discarding/confirming that lead:

(require 'benchmark)
(format "%.8f" (benchmark-elapse (cider-current-repl)))

It returns 0.00005400 for me (and it successfully finds a repl - please make sure of that) - seems fast enough to be repeatedly invoked.

from clojure-mode.

Apparently "electric / aggressive indentation modes" can query cider-current-repl which can be relatively slow, and noticeably slow if repeated enough times.

I think this is the right direction, because I think I just found a huge supporting clue of several parts:

• when there are 0 REPLs running, indentation is instant; I don't see a progress % in minibuffer
• while cider-connected to a babashka REPL in the current buffer, indentation is fast enough but I do notice a flicker of progress % in the minibuffer and there's a noticeable subsecond lag
• while that babashka REPL is running elsewhere, indentation in my clojuredart buffer (clojure-mode but no REPL) is very very slow (for the same form as in babashka buffer!)

from clojure-mode.

Thanks!

Could you please (benchmark-elapse (cider-current-repl)) for each case?

Expanding on that, (cider-current-repl) can invoke a function named cider--sesman-friendly-session-p.

Assuming a given (cider-current-repl) call for a specific scenario is slow, please also benchmark (cider-debug-sesman-friendly-session-p) which is a special defun that exercises cider--sesman-friendly-session-p. It's sensitive to the current buffer you invoke it from (with M-:)

If (cider-debug-sesman-friendly-session-p) performs slowly, please profile it and share which specific function calls within it are to blame for the slowness.

from clojure-mode.

for (benchmark-elapse (cider-current-repl)):

• bb with 0 repls: 9.2e-05
• bb while bb runs: 0.000129
• .cljd with 0 repls: 0.000108
• .cljd while bb runs: 0.000149

for (benchmark-elapse (cider-debug-sesman-friendly-session-p)):

• bb with 0 repls: 0.000557
• bb while bb runs: 0.037627
• .cljd with 0 repls: 0.000507
• .cljd while bb runs: 0.09996 👀

profile-report

M-:, (cider-debug-sesman-friendly-session-p)

         225  78% - command-execute
         225  78%  - call-interactively
         225  78%   - apply
         225  78%    - call-interactively@ido-cr+-record-current-command
         225  78%     - #<subr call-interactively>
         161  56%      - funcall-interactively
         129  45%       - smex
          95  33%        - smex-read-and-run
          90  31%         - smex-completing-read
          90  31%          - ido-completing-read
          90  31%           - apply
          90  31%            - ido-completing-read@ido-cr+-replace
          90  31%             - #<subr ido-completing-read>
          90  31%              - ido-read-internal
          40  13%               - read-from-minibuffer
          21   7%                - ido-exhibit
          21   7%                 - apply
          21   7%                  - #<subr ido-exhibit>
          13   4%                   - ido-set-matches
          13   4%                    - ido-set-matches-1
          13   4%                     - mapc
           4   1%                        #<compiled -0x1096ba985ec5e99a>
           3   1%                   + ido-set-common-completion
           4   1%                + timer-event-handler
           3   1%                + redisplay_internal (C function)
           1   0%                + ido-tidy
           1   0%                + sp--save-pre-command-state
           1   0%                + command-execute
           1   0%                + minibuffer-inactive-mode
           3   1%               + ido-set-matches
           4   1%         + execute-extended-command
          23   8%        + smex-update
          10   3%        + smex-detect-new-commands
          32  11%       + eval-expression
          63  22%      + byte-code
          39  13% + ...
          15   5% + timer-event-handler
           7   2% + redisplay_internal (C function)

from clojure-mode.

.cljd while bb runs: 0.09996 👀

Good find!

The profiling doesn't appear to capture cider-debug-sesman-friendly-session-p's body - I can only see smex (M-x) stuff there.

I tried profiling it myself now but I can't get it to show up in the report.

I'll be happy to optimize cider-debug-sesman-friendly-session-p once we find what's slow in it.

from clojure-mode.

Hey @daveliepmann , regardless of the profiling, I went ahead and improved that function since it was evident that it could be optimized:

clojure-emacs/cider#3463

I'd much appreciate if you can try it locally. If you use ELPA, one way is to download those two files, place them in ~/.emacs.d/elpa/cider*, remove any .elc files and restart Emacs.

from clojure-mode.

Hey @daveliepmann , regardless of the profiling, I went ahead and improved that function since it was evident that it could be optimized:

clojure-emacs/cider#3463

I'd much appreciate if you can try it locally. If you use ELPA, one way is to download those two files, place them in ~/.emacs.d/elpa/cider*, remove any .elc files and restart Emacs.

Thanks, I really appreciate you chasing these leads. I got those two files downloaded and running and see no change. (I confirmed they were the running code with describe-mode and some jump-to-def, though I didn't see any .elc files to delete — not sure if that could be an issue?)

I also noticed that the slowdown in the clojure-mode-but-no-CIDER-REPL only occurs when there's a cider-connect'd babashka REPL running elsewhere, not when I have a cider-jack-in'd-JVM-REPL running elsewhere with the following start-up command:

;;  Startup: bash /Users/daveliepmann/.emacs.d/elpa/cider-20230911.1428/clojure.sh /opt/homebrew/bin/clojure -Sdeps \{\:deps\ \{nrepl/nrepl\ \{\:mvn/version\ \"1.0.0\"\}\ cider/cider-nrepl\ \{\:mvn/version\ \"0.37.0\"\}\ refactor-nrepl/refactor-nrepl\ \{\:mvn/version\ \"3.6.0\"\}\}\ \:aliases\ \{\:cider/nrepl\ \{\:main-opts\ \[\"-m\"\ \"nrepl.cmdline\"\ \"--middleware\"\ \"\[refactor-nrepl.middleware/wrap-refactor\,cider.nrepl/cider-middleware\]\"\]\}\}\} -M:cider/nrepl

from clojure-mode.

I see!

What's the value of (benchmark-elapse (cider-debug-sesman-friendly-session-p)) for the problematic buffer?

from clojure-mode.

What's the value of (benchmark-elapse (cider-debug-sesman-friendly-session-p)) for the problematic buffer?

0.028764

from clojure-mode.

Before it was 0.09996, right?

It's still a progress but still not quite right.

For a comparable case (I have 1 repl around, and invoke (benchmark-elapse (cider-debug-sesman-friendly-session-p)) in a buffer that is not related to that repl), it takes 0.00251 for me.

Perhaps the sesman-friendly-session-p code contributed to the slowness but there's some other source of slowness?

As you point out:

also noticed that the slowdown in the clojure-mode-but-no-CIDER-REPL only occurs when there's a cider-connect'd babashka REPL running elsewhere, not when I have a cider-jack-in'd-JVM-REPL running elsewhere with the following start-up command: [...]

...I don't know what it could be. A successful profiling session could help.

Try indenting code while profiling, to trigger the slow code path?

from clojure-mode.

profiler report while indenting code (slowly)

from clojure-mode.

Thanks much!

I've upgraded clojure-emacs/cider#3463. Before, even though nothing was 'broken', the cache wasn't being hit.

Now it is. I have verified so with numbers: for a 'non-friendly' buffer, runtime has improved from 0.00251 to 0.0003.

from clojure-mode.

I updated to the latest from that PR and profiled again; results in cpu-profiler-report2. seemed marginally faster at best

from clojure-mode.

Thanks!

I don't see a smoking gun.

Could you please perform the following?

• (setq inhibit-message t)
  • this ensures the following benchmark won't be distorted by output printing
• (benchmark-elapse (cider-debug-sesman-friendly-session-p)) within the problematic buffer
  • A handful of times please

from clojure-mode.

sure

(lightly edited)

benchmark
(("path/to/app.cljd" "was not determined to belong to classpath:" nil "or classpath-roots:" nil))
0.032754
(("path/to/app.cljd" "was not determined to belong to classpath:" nil "or classpath-roots:" nil))
0.030909
(("path/to/app.cljd" "was not determined to belong to classpath:" nil "or classpath-roots:" nil))
0.032258
(("path/to/app.cljd" "was not determined to belong to classpath:" nil "or classpath-roots:" nil))
0.028817
(("path/to/app.cljd" "was not determined to belong to classpath:" nil "or classpath-roots:" nil))
0.030899

from clojure-mode.

Thanks, interesting.

What's the output of M-: cider--sesman-friendly-session-result within that buffer?

from clojure-mode.

(dict #<buffer *cider-repl knowuro-cljd/bb:localhost:1667(clj)*> nil)

from clojure-mode.

Thanks!

Is this part "was not determined to belong to classpath:" nil "or classpath-roots:" nil reproduced as-is?

...That would mean that babashka is returning a nil classpath, which might have to do with the whole thing.

In addition, please visit the bb repl and eval both of these individually (after having reproduced the issue one more time):

(cider-classpath-entries)
(process-get (get-buffer-process (current-buffer)) :cached-classpath)
(process-get (get-buffer-process (current-buffer)) :cached-classpath-roots)
(process-get (get-buffer-process (current-buffer)) :cached-all-namespaces)

What does each expr return?

from clojure-mode.

Is this part "was not determined to belong to classpath:" nil "or classpath-roots:" nil reproduced as-is?

Correct, that is as-is. I just elided the path on my machine.

(cider-classpath-entries) => nil
(process-get (get-buffer-process (current-buffer)) :cached-classpath) => nil
(process-get (get-buffer-process (current-buffer)) :cached-classpath-roots) => nil
(process-get (get-buffer-process (current-buffer)) :cached-all-namespaces) => nil

from clojure-mode.

Thanks.

So, the process isn't holding any of the big objects to be cached. Maybe that's related to the nature of bb? Since it's an nrepl server I'd imagine it's a persistent process, but also bb is oriented towards one-off things (i.e., they run and complete very quickly) so maybe something is 'one-off' there?

That would mean a bb repl is unable to cache anything.

Does that ring a bell?

from clojure-mode.

I'm not qualified to answer for bb; maybe @borkdude knows?

from clojure-mode.

The exact question is whether cider's nrepl-server process that is backed by bb is a "true" persistent server, or contrariwise something that is spawned on demand for each request.

Not sure if Michiel implemented that, but he might know!

from clojure-mode.