Indentation very slow on 20230911.1653 #665

daveliepmann · 2023-09-12T08:27:43Z

As part of clojure-emacs/cider#3456 I just upgraded to clojure-mode-20230911.1653, which seems to have caused a tremendous performance regression around indenting forms.

Expected behavior

Indentation is fast enough not to interrupt flow

Actual behavior

A ~30-line let or do now takes just under 10 seconds to indent.

A ~400-line buffer froze emacs for about a minute while indenting.

Carriage return at the end of a line has a sub-second but noticeable delay.

(Relatively consistent map literals seem significantly faster)

Steps to reproduce the problem

Write a large form then add a do or let

or

given the following clojuredart form, add and remove the newline before :get:

(f/widget :get {the-nav m/Navigator}
            m/Card
            ;; TODO
            #_ (m/InkWell .onTap (push-fn the-nav (scrn=book book-id)))
            (m/ListTile .leading (m/Icon m/Icons.table_chart_rounded)
                        .title (m/Text "Flowcharts")))

Environment & Version information

clojure-mode version

clojure-mode (version nil) per #658

clojure-mode-20230911.1653 by directory

Emacs version

GNU Emacs 28.2 (build 1, aarch64-apple-darwin22.1.0, Carbon Version 169 AppKit 2299) of 2022-12-10

Operating system

macOS ventura

The text was updated successfully, but these errors were encountered:

vemv · 2023-09-12T08:35:17Z

Thanks much for the report!

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

vemv · 2023-09-12T09:11:44Z

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?

daveliepmann · 2023-09-12T09:15:06Z

thanks for looking into this!

electric-indent, yes

vemv · 2023-09-12T09:19:46Z

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.

vemv · 2023-09-12T09:27:22Z

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.

vemv · 2023-09-12T09:53:47Z

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.

daveliepmann · 2023-09-12T18:38:28Z

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!)

vemv · 2023-09-12T20:39:13Z

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.

daveliepmann · 2023-09-12T21:07:21Z

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)

vemv · 2023-09-13T05:41:00Z

.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.

vemv · 2023-09-13T07:12:37Z

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.

daveliepmann · 2023-09-13T07:38:20Z

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

vemv · 2023-09-13T10:33:33Z

I see!

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

vemv · 2023-09-13T10:34:44Z

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.

daveliepmann · 2023-09-13T10:37:59Z

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

0.028764

vemv · 2023-09-13T10:43:07Z

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?

daveliepmann · 2023-09-13T11:29:07Z

profiler report while indenting code (slowly)

vemv · 2023-09-13T11:55:58Z

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.

daveliepmann · 2023-09-13T18:56:16Z

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

vemv · 2023-09-13T19:02:11Z

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

daveliepmann · 2023-09-13T19:19:22Z

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

vemv · 2023-09-13T19:21:27Z

Thanks, interesting.

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

daveliepmann · 2023-09-13T19:26:00Z

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

vemv · 2023-09-13T19:32:38Z

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?

daveliepmann · 2023-09-13T19:36:36Z

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

vemv · 2023-09-13T19:42:33Z

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?

daveliepmann · 2023-09-13T19:56:52Z

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

vemv · 2023-09-13T20:00:00Z

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!

borkdude · 2023-09-13T20:10:14Z

The server is persistent.

This speeds up `(cider-current-repl)` performance in non-linked buffers from to 0.01s to 0.00098800s. Because `(cider-current-repl)` can be repeatedly invoked by e.g. `electric-indent-mode`, it makes a difference. Fixes clojure-emacs/clojure-mode#665

vemv mentioned this issue Sep 13, 2023

Add buffer-local caching to friendly-session calculation clojure-emacs/cider#3463

Draft

vemv mentioned this issue Sep 28, 2023

cider--sesman-friendly-session-p: check for ns-list op availability clojure-emacs/cider#3488

Merged

bbatsov closed this as completed in clojure-emacs/cider#3488 Sep 29, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Indentation very slow on 20230911.1653 #665

Indentation very slow on 20230911.1653 #665

daveliepmann commented Sep 12, 2023

vemv commented Sep 12, 2023

vemv commented Sep 12, 2023

daveliepmann commented Sep 12, 2023 •

edited

Loading

vemv commented Sep 12, 2023

vemv commented Sep 12, 2023

vemv commented Sep 12, 2023

daveliepmann commented Sep 12, 2023

vemv commented Sep 12, 2023

daveliepmann commented Sep 12, 2023

vemv commented Sep 13, 2023

vemv commented Sep 13, 2023

daveliepmann commented Sep 13, 2023 •

edited

Loading

vemv commented Sep 13, 2023

vemv commented Sep 13, 2023 •

edited

Loading

daveliepmann commented Sep 13, 2023

vemv commented Sep 13, 2023

daveliepmann commented Sep 13, 2023 •

edited

Loading

vemv commented Sep 13, 2023

daveliepmann commented Sep 13, 2023

vemv commented Sep 13, 2023

daveliepmann commented Sep 13, 2023

vemv commented Sep 13, 2023

daveliepmann commented Sep 13, 2023

vemv commented Sep 13, 2023

daveliepmann commented Sep 13, 2023 •

edited

Loading

vemv commented Sep 13, 2023 •

edited

Loading

daveliepmann commented Sep 13, 2023

vemv commented Sep 13, 2023

borkdude commented Sep 13, 2023

Indentation very slow on 20230911.1653 #665

Indentation very slow on 20230911.1653 #665

Comments

daveliepmann commented Sep 12, 2023

Expected behavior

Actual behavior

Steps to reproduce the problem

Environment & Version information

clojure-mode version

Emacs version

Operating system

vemv commented Sep 12, 2023

vemv commented Sep 12, 2023

daveliepmann commented Sep 12, 2023 • edited Loading

vemv commented Sep 12, 2023

vemv commented Sep 12, 2023

vemv commented Sep 12, 2023

daveliepmann commented Sep 12, 2023

vemv commented Sep 12, 2023

daveliepmann commented Sep 12, 2023

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

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

profile-report

vemv commented Sep 13, 2023

vemv commented Sep 13, 2023

daveliepmann commented Sep 13, 2023 • edited Loading

vemv commented Sep 13, 2023

vemv commented Sep 13, 2023 • edited Loading

daveliepmann commented Sep 13, 2023

vemv commented Sep 13, 2023

daveliepmann commented Sep 13, 2023 • edited Loading

vemv commented Sep 13, 2023

daveliepmann commented Sep 13, 2023

vemv commented Sep 13, 2023

daveliepmann commented Sep 13, 2023

vemv commented Sep 13, 2023

daveliepmann commented Sep 13, 2023

vemv commented Sep 13, 2023

daveliepmann commented Sep 13, 2023 • edited Loading

vemv commented Sep 13, 2023 • edited Loading

daveliepmann commented Sep 13, 2023

vemv commented Sep 13, 2023

borkdude commented Sep 13, 2023

daveliepmann commented Sep 12, 2023 •

edited

Loading

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

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

daveliepmann commented Sep 13, 2023 •

edited

Loading

vemv commented Sep 13, 2023 •

edited

Loading

daveliepmann commented Sep 13, 2023 •

edited

Loading

daveliepmann commented Sep 13, 2023 •

edited

Loading

vemv commented Sep 13, 2023 •

edited

Loading