Cider buffered printing strategy doesn't work with large files as intended

[joinr]

Expected behavior

Cider 0.21 should - upon trying to print large amounts of text (e.g. > 1mb) gracefully halt for us, and during printing, print in chunks as to enable user interruption.

Actual behavior

When working with a ~3mb tab delimited text file, Cider tries to chunk print, but grinds to a halt as emacs starts to freeze. If user is fast enough and interrupts, the REPL is recoverable (this must happen within the first few chunks of printing). If user does not interrupt, and lets the printing continue unabated, Cider does not seem to reach the graceful cutoff point (I let it run for about 30s just to see). User can interrupt cider only with (cider-interrupt). At that point, REPL prompt reappears, but further evaluation is disabled. It seems like the nREPL process is hung up. CPU utilization confirms emacs is still grinding trying to do something (20% vs. 0% resting).

Steps to reproduce the problem

Given the uncompressed raw text file stored in gzipped format here at path "path-to-file", from the repl:

    (def path "path-to-file")
    (def res (slurp path))
    res  ;;if not interrupted immediately, this will hang the repl
    ;;we can get similar behavior if we slurp the file directly and print the output
    ;;e.g. (slurp path), with no intermediate binding to res.

Environment & Version information

CIDER version information

CIDER 0.21.0 (New York), nREPL 0.6.0 Clojure 1.10.0, Java 1.8.0_181

Lein/Boot version

leiningen 2.9.1

Emacs version

25.3

Operating system

Windows 10

[bbatsov]

Thanks for the report! We'll investigate this further. //cc @cichli I have some doubts that this might be some poor interaction with the content-type middleware in cider-nrepl, but this has to be confirmed.

[andreyorst]

I'm not sure if this should be a separate issue or falls into this one, but rapid printing inside CIDER's REPL in general hangs Emacs pretty hard. E.g. the following code hangs Emacs without ability to interrupt or recover it:

(doseq [i (range)] (println i))

If I call the same thing in C-u M-x inferior-lisp RET clojure RET it doesn't hang and prints very fast.

Additional info, when I force my way through, eighter by killing the java process, and killing the REPL buffer, or being lucky enough for interrupt action to register, Emacs is still pretty much hanging, continuing printing buffered text, and probably collecting a lot of garbage, as it seems.

This is very annoying when I do debugging via printing, and there are tight loops I want to debug. Basically I have to insert (Thread/sleep 300) after such prints to be sure that I will not hang Emacs.

[andreyorst]

Running the (dotimes [i 200000] (println i)) snippet results in a significant slowdown in the REPL, making emacs hang completely at some point (tested with emacs -Q). Doing a CPU profiling at the same time the report shows a lot of GC and some slowness in the nrepl-client-filter.

I was hoping that solving #3219 would also make this case less problematic but the behavior seems unchanged.

CPU profiling report

``` 23860 72% - ... 23860 72% Automatic GC 9056 27% - nrepl-client-filter 5368 16% - nrepl--dispatch-response 5264 15% - # 5073 15% - # 4623 14% - # 4615 13% - cider-repl-emit-stdout 1306 3% - cider-repl--emit-output 501 1% - cider-run-chained-hook 117 0% ansi-color-apply 38 0% cider-repl-highlight-spec-keywords 5 0% cider-repl-highlight-current-project 376 1% - jit-lock-after-change 217 0% run-hook-with-args 55 0% - eval 36 0% - if 2 0% display-graphic-p 1 0% frame-parameter 5 0% - unless 1 0% if 8 0% syntax-ppss-flush-cache 3 0% undo-auto--undoable-change 324 0% - nrepl-dict-get 181 0% - nrepl-dict-contains 36 0% nrepl-dict-keys 17 0% lax-plist-get 67 0% - cider-set-buffer-ns 67 0% - cider-refresh-dynamic-font-lock 62 0% - font-lock-flush 62 0% jit-lock-refontify 5 0% - cider--compile-font-lock-keywords 4 0% - # 3 0% - seq-find 3 0% - seq-do 3 0% - mapc 3 0% - # 1 0% # 1 0% nrepl-dict-get 1 0% - regexp-opt 1 0% - regexp-opt-group 1 0% - regexp-opt-group 1 0% regexp-opt-group 47 0% - cider-eval-spinner 42 0% - nrepl-dict-get 24 0% - nrepl-dict-contains 5 0% nrepl-dict-keys 31 0% - nrepl-dict-get 19 0% - nrepl-dict-contains 2 0% nrepl-dict-keys 62 0% - nrepl-dict-get 19 0% - nrepl-dict-contains 1 0% nrepl-dict-keys 6 0% lax-plist-get 3286 9% - nrepl-bdecode 3264 9% - nrepl--bdecode-message 3245 9% - nrepl--bdecode-1 3210 9% - nrepl--bdecode-list 2504 7% - nrepl--bdecode-1 234 0% - replace-regexp-in-string 111 0% # 13 0% - nrepl--bdecode-list 13 0% - nrepl--bdecode-1 13 0% - nrepl--bdecode-list 13 0% - nrepl--bdecode-1 13 0% - nrepl--bdecode-list 13 0% - nrepl--bdecode-1 9 0% - nrepl--bdecode-list 9 0% - nrepl--bdecode-1 2 0% - replace-regexp-in-string 2 0% # 277 0% - run-hook-with-args 266 0% - cider-repl--state-handler 176 0% - nrepl-dict-get 110 0% - nrepl-dict-contains 6 0% nrepl-dict-keys 82 0% - cider-refresh-dynamic-font-lock 63 0% - font-lock-flush 63 0% jit-lock-refontify 19 0% - cider--compile-font-lock-keywords 10 0% - regexp-opt 10 0% - regexp-opt-group 10 0% - regexp-opt-group 10 0% - regexp-opt-group 10 0% - regexp-opt-group 10 0% - regexp-opt-group 9 0% - regexp-opt-group 6 0% - regexp-opt-group 6 0% - regexp-opt-group 6 0% - regexp-opt-group 6 0% - regexp-opt-group 6 0% - regexp-opt-group 6 0% - regexp-opt-group 6 0% - regexp-opt-group 6 0% - regexp-opt-group 6 0% - regexp-opt-group 6 0% regexp-opt-group 9 0% - # 4 0% - seq-find 3 0% - seq-do 1 0% mapc 2 0% - nrepl-dict-get 1 0% nrepl-dict-contains 1 0% lax-plist-get 39 0% - redisplay_internal (C function) 19 0% - jit-lock-function 11 0% - jit-lock-fontify-now 5 0% - jit-lock--run-functions 5 0% - run-hook-wrapped 5 0% - # 3 0% - font-lock-fontify-region 2 0% - # 2 0% - cider--update-locals-for-region 2 0% - cider--parse-and-apply-locals 2 0% - cider--read-locals-from-arglist 2 0% - cider-start-of-next-sexp 2 0% forward-sexp 1 0% font-lock-set-defaults 7 0% - eval 7 0% if 4 0% - redisplay--pre-redisplay-functions 1 0% run-hook-with-args 2 0% mode-line-default-help-echo 1 0% - funcall 1 0% # 1 0% kill-this-buffer-enabled-p 9 0% - timer-event-handler 5 0% - apply 2 0% - # 2 0% jit-lock-context-fontify 2 0% - # 2 0% - eldoc-print-current-symbol-info 2 0% - eldoc--invoke-strategy 2 0% - eldoc-documentation-default 2 0% - run-hook-with-args-until-success 2 0% - cider-eldoc 2 0% - cider-eldoc-info-in-current-sexp 2 0% - cider-eldoc-info-at-point 1 0% - cider-in-comment-p 1 0% - beginning-of-defun 1 0% - beginning-of-defun-raw 1 0% - cider-repl-mode-beginning-of-defun 1 0% - cider-repl-previous-prompt 1 0% cider-repl--find-prompt 3 0% - timer-inc-time 3 0% timer-relative-time 1 0% timer-until 8 0% - command-execute 8 0% - funcall-interactively 7 0% - profiler-start-or-report 7 0% if ```

A lot of times this happens unexpectedly when I decide to add logging to some tight loop to debug it, and I often have to kill the java process to make emacs responsible again. Which kills the program's state, though it is less painful when Emacs crashes because of this (which happened to me a few times).

When printing a large string, as described in the issue, the situation is almost the same - most of the time spent collecting garbage:

CPU profiling for large file

``` 632 85% - ... 632 85% Automatic GC 53 7% - timer-event-handler 31 4% - apply 28 3% - # 28 3% - eldoc-print-current-symbol-info 28 3% - eldoc--invoke-strategy 28 3% - eldoc-documentation-default 28 3% - run-hook-with-args-until-success 28 3% - cider-eldoc 28 3% - cider-eldoc-info-in-current-sexp 27 3% - cider-eldoc-info-at-point 25 3% - cider-eldoc-info 25 3% - cider-sync-request:eldoc 25 3% - cider-nrepl-send-sync-request 6 0% - nrepl-send-sync-request 5 0% - nrepl-client-filter 5 0% - nrepl--dispatch-response 5 0% - # 5 0% - # 5 0% - # 4 0% - cider-repl-emit-result 4 0% - cider-font-lock-as-clojure 4 0% - cider-font-lock-as 3 0% - font-lock-fontify-region 3 0% - font-lock-default-fontify-region 1 0% - font-lock-fontify-syntactically-region 1 0% font-lock-default-fontify-syntactically 1 0% - cider--make-buffer-for-mode 1 0% seq-filter 1 0% - timer-event-handler 1 0% - apply 1 0% # 2 0% - cider-eldoc-beginning-of-sexp 2 0% - clojure-backward-logical-sexp 2 0% - backward-sexp 2 0% forward-sexp 1 0% - cider-eldoc-info-at-sexp-beginning 1 0% - cider-eldoc-beginning-of-sexp 1 0% - clojure-backward-logical-sexp 1 0% - backward-sexp 1 0% forward-sexp 1 0% # 8 1% - timer-inc-time 7 0% timer-relative-time 2 0% cancel-timer-internal 2 0% - timer-activate 2 0% - timer--activate 2 0% timer--time-less-p 2 0% timer-until 47 6% - redisplay_internal (C function) 12 1% - eval 9 1% - if 1 0% display-graphic-p 1 0% mode-line-eol-desc 1 0% unless 10 1% menu-bar-update-buffers 5 0% kill-this-buffer-enabled-p 3 0% redisplay--pre-redisplay-functions 3 0% - funcall 3 0% - # 3 0% - gui-backend-selection-exists-p 2 0% - apply 2 0% # 2 0% - jit-lock-function 2 0% - jit-lock-fontify-now 2 0% - jit-lock--run-functions 1 0% - run-hook-wrapped 1 0% - # 1 0% font-lock-fontify-region 2 0% - mode-line-default-help-echo 2 0% - window-at-side-p 1 0% window-pixel-edges 2 0% tool-bar-make-keymap 5 0% - command-execute 5 0% - funcall-interactively 3 0% - profiler-start-or-report 3 0% - if 1 0% - profiler-report 1 0% - profiler-report-cpu 1 0% - profiler-report-profile-other-window 1 0% - profiler-report-setup-buffer 1 0% - profiler-report-render-calltree 1 0% - profiler-report-rerender-calltree 1 0% - profiler-report-render-calltree-1 1 0% - profiler-calltree-sort 1 0% - profiler-calltree-sort 1 0% - profiler-calltree-sort 1 0% - profiler-calltree-sort 1 0% - profiler-calltree-sort 1 0% profiler-calltree-sort 2 0% - cider-repl-return 2 0% - cider-repl--send-input 2 0% - cider-nrepl-request:eval 2 0% - nrepl-request:eval 2 0% - nrepl-send-request 2 0% nrepl-bencode 5 0% - nrepl-client-filter 5 0% - nrepl--dispatch-response 5 0% - # 5 0% - # 5 0% - # 5 0% - cider-repl-emit-result 5 0% - cider-font-lock-as-clojure 5 0% - cider-font-lock-as 3 0% - font-lock-fontify-region 3 0% font-lock-default-fontify-region 1 0% check-parens ```

[joinr]

I wonder if it's somehow related to pprint (which I think is what cider is actually using by default, and is an implicit "gotcha").

[vemv]

My 2c - the 1MB limiting works as intended, from what I can see, but even when that is accomplished, it does not suffice to prevent Emacs from suffering.

As it's well-known, basically any long line will make Emacs struggle.

We use pprint, which play to our advantage, since most times it means that no long lines are generated.

So, a common red path is when:

• we're not pprinting; and
• the line is long (100KB is a lot , for instance, for a single line).

Perhaps repl printing internals could have some sort of "long line avoidance" mechanism? Don't know if it's been attempted before.

I'd imagine that it can easily backfire in terms of performance - running logic on every insert can be expensive. But perhaps there's opportunity.