REPL slow when processing long outputs

[sebastianpoeplau]

Expected behavior

When running code which produces a lot of output in the CIDER REPL buffer, the output should show reasonably fast (within the limits of Emacs' capabilities regarding buffer updates).

Actual behavior

The REPL window hangs for quite some time before showing the output (see reproducing example below). The profiler suggests that cider-repl--emit-output is the culprit. I've experimented a bit with it, and it seems that the problem is caused by the part that scrolls the output window if necessary:

  (when-let* ((window (get-buffer-window buffer t)))
    ;; If the prompt is on the first line of the window, then scroll the window
    ;; down by a single line to make the emitted output visible.
    (when (and (pos-visible-in-window-p cider-repl-prompt-start-mark window)
               (< 1 cider-repl-prompt-start-mark)
               (not (pos-visible-in-window-p (1- cider-repl-prompt-start-mark) window)))
      (with-selected-window window
        (scroll-down 1))))

Commenting out this part of the function makes the problem disappear (while the REPL keeps working except for the logic that scrolls the window if the prompt happens to be on the first line). In particular, pos-visible-in-window-p seems to be really slow; note how replacing the block above with just (pos-visible-in-window-p cider-repl-prompt-start-mark) shows the same problematic behavior.

Steps to reproduce the problem

Start a CIDER session and define the following function:

(defn output-a-lot []
  (dotimes [_ 100]
    (println (range 1000))))

Call the function from the REPL buffer; the output should take several seconds to appear (adjust the loop count if necessary). Try to remove the part of cider-repl--emit-output mentioned above, evaluate the change, and call output-a-lot again in the REPL; the output should now appear more or less immediately.

Environment & Version information

CIDER version information

;; CIDER 1.5.0-snapshot (package: 1.5.0-snapshot), nREPL 0.8.3
;; Clojure 1.10.3, Java 11.0.15

Lein / Clojure CLI version

Leiningen 2.9.8 on Java 11.0.15 OpenJDK 64-Bit Server VM

Emacs version

GNU Emacs 27.1 (build 1, x86_64-pc-linux-gnu, GTK+ Version 3.24.30, cairo version 1.16.0) of 2022-01-24, modified by Debian

Operating system

Ubuntu 22.04

JDK distribution

openjdk version "11.0.15" 2022-04-19
OpenJDK Runtime Environment (build 11.0.15+10-Ubuntu-0ubuntu0.22.04.1)
OpenJDK 64-Bit Server VM (build 11.0.15+10-Ubuntu-0ubuntu0.22.04.1, mixed mode, sharing)

[bbatsov]

That's a long-standing issue that has to be fixed in Emacs itself. See the discussion here #1115

Supposedly Commercial Emacs (https://github.com/commercial-emacs/commercial-emacs) has patched this to some extent, but I've never tried it myself.

[sebastianpoeplau]

Interesting discussion, thanks for the pointer!

I guess my suggestion was to disable the "scroll back one line to make REPL output visible" feature (or make it configurable) while we're waiting for a fix in Emacs. Determining whether cider-repl-prompt-start-mark is visible seems to be the main cause for the slowness; I agree that this needs to be fixed in Emacs itself, but if we can circumvent the issue at the cost of a convenience feature (i.e., by not scrolling new output into view when the prompt is at the very top of the REPL window), maybe that's a worthwhile tradeoff at least for some users 🤔 I know it would be for me 😊 I'll be happy to add a customize option if that's fine with you...

[bbatsov]

I'll be happy to add a customize option if that's fine with you...

That would be fine by me.

[andreyorst]

That's a long-standing issue that has to be fixed in Emacs itself

There might be a separate issue here, not related to long lines at all, as CIDER locks up when doing any kind of rapid output to the repl, like:

(dotimes [_ Integer/MAX_VALUE]
  (println 0))

This hangs Emacs completely. This also doesn't hang emacs if Clojure is started via C-u M-x inferior-lisp RET clojure RET, so this is a CIDER problem. This is tracked by #2635, I believe

[bo-tato]

I'll try and look at this again in a couple months when I've learned emacs and elisp some more cause it's beyond my current abilities to investigate, but when I run the emacs profiler and do a println loop, it shows most time is being spent in nrepl-client-filter

[bo-tato]

I didn't fully read the issue haha, @sebastianpoeplau had already tracked down the code called by nrepl-client-filter responsible for most of the slowdown. I can confirm when I comment out that when-let* block he identifies, it improves the performance almost 10x (repl prints 2000 lines of output in 2 seconds instead of 16). But the most interesting thing is I don't observe any change in behaviour of repl. If I am scrolled to the bottom of the repl, after output it will still be scrolled to the bottom, which I think is what that when-let* is supposed to do. I triple checked I had loaded the modified version with it commented out, (and the speedup is obvious so it had to be running the commented out version). If the repl is scrolled up it stays scrolled at that point but that is the original and expected behaviour also. Maybe that when-let* block scrolling the output is not needed?

[bbatsov]

I guess my suggestion was to disable the "scroll back one line to make REPL output visible" feature (or make it configurable) while we're waiting for a fix in Emacs. Determining whether cider-repl-prompt-start-mark is visible seems to be the main cause for the slowness;

@bo-tato As I replied earlier to @sebastianpoeplau I think it's fine to make this configurable and disabled by default, as it seems most people are not really bothered by a different behavior.

If I am scrolled to the bottom of the repl, after output it will still be scrolled to the bottom, which I think is what that when-let* is supposed to do.

As noted above this works differently:

Commenting out this part of the function makes the problem disappear (while the REPL keeps working except for the logic that scrolls the window if the prompt happens to be on the first line).

[bbatsov]

Basically to see the problem you need to recenter your REPL with C-l to illustrate the problem. If the prompt is not first line of the window and you output something in the REPL you won't see it as it will be printed before the REPL prompt. Admitted, this should happen often unless you're in the habit like me to keep pulling your prompt to the top of the REPL buffer.

[bbatsov]

Anyways, I decided it's easiest for me to make this change. Hopefully everyone will agree it's for the better.

[bbatsov]

P.S. Here's also the backstory for the problematic (slow) code #2595