Indentation very slow on 20230911.1653

daveliepmann commented 1 year ago

As part of https://github.com/clojure-emacs/cider/issues/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

vemv commented 1 year ago

Thanks much for the report!

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

vemv commented 1 year ago

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 commented 1 year ago

thanks for looking into this!

electric-indent, yes

vemv commented 1 year ago

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 commented 1 year ago

Here's a possible lead https://github.com/clojure-emacs/cider/issues/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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

.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 commented 1 year ago

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

https://github.com/clojure-emacs/cider/pull/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 commented 1 year ago

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 commented 1 year ago

I see!

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

vemv commented 1 year ago

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 commented 1 year ago

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

0.028764

vemv commented 1 year ago

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 commented 1 year ago

profiler report while indenting code (slowly)

vemv commented 1 year ago

Thanks much!

I've upgraded https://github.com/clojure-emacs/cider/pull/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 commented 1 year ago

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

vemv commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

Thanks, interesting.

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

daveliepmann commented 1 year ago

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

vemv commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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

vemv commented 1 year ago

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 commented 1 year ago

The server is persistent.

clojure-emacs / clojure-mode