Cider locks up Emacs regularly after cider-connect

[mrrodriguez]

Expected behavior

When using cider-connect to connect to a pre-existing nREPL server, I expect it to connect and be responsive once the prompt is available. As I continue to interact and work in the REPL I do not expect frequent lock-ups that lock up Emacs itself, not only the REPL prompt.

Actual behavior

I use cider-connect to connect to a pre-existing nREPL server. I get a prompt fairly quickly with something like

user>

However, if I try to type any character, Emacs/Cider becomes fully locked up. This lasts for anywhere from 5-10 seconds. Once it becomes responsive again, some characters I typed during the lock-up typically show up. Then I can start requiring my namespaces etc. This all happens at normal speeds at this point. However, frequently as I am doing more work in the editor with this connection present, I get frequent lock-ups again that lock the whole editor. I do not know what it is doing during this time.

Steps to reproduce the problem

My steps above are all you need to do to see this problem.

Environment & Version information

CIDER version information

;; CIDER 0.12.0  nREPL 0.2.12
;; Clojure 1.8.0, Java 1.8.0_91

Note: I see the same behavior in Java 6 as well.

Lein/Boot version

Lein 2.6.1

Emacs version

GNU Emacs 24.5.1 (x86_64-apple-darwin13.4.0, NS apple-appkit-1265.21) of 2015-04-10 on builder10-9.porkrind.org

Operating system

OS X 10.11.4 "El Capitan"

[Malabarba]

1. Do M-x toggle-debug-on-quit.
2. Reproduce the hang (or wait for it to happen)
3. Hit C-g while it's hanged.

You'll get a backtrace you can paste here.

[mrrodriguez]

This is from when it was locking up immediately after the Cider REPL prompt buffer prompt showed up after cider-connect.

Debugger entered--Lisp error: (quit)
  redisplay_internal\ \(C\ function\)()
  read-event(nil t 2)
  sit-for(2)
  execute-extended-command(nil "cider-connect")
  smex-read-and-run(("cider-connect" "eldoc-mode" "toggle-debug-on-quit" "comment-region" "goto-line" "delete-rectangle" "eval-last-sexp" "cider-repl-clear-buffer" "fill-paragraph" "cider-change-buffers-designation" "clojure-mode" "describe-key" "replace-string" "cider-mode" "describe-variable" "cider-drink-a-sip" "paredit-mode" "query-replace" "eval-expression" "describe-function" "other-frame" "delete-frame" "set-fill-column" "eshell" "eval-buffer" "cider-version" "package-list-packages" "desktop-change-dir" "eval-region" "desktop-save" "other-window" "indent-region" "ispell-region" "indent-rigidly" "package-install" "cider-report-bug" "cider-view-refcard" "cider-eval-last-sexp" "cider-apropos-documentation" "cider-jack-in" "describe-mode" "emacs-version" "yank-rectangle" "cider-view-manual" "cider-repl-history-save" "cider-connection-browser" "package-refresh-contents" "cider-debug-toggle-locals" "clojure-mode-display-version" "cider-find-and-clear-repl-output" ...))
  smex()
  #<subr call-interactively>(smex nil nil)
  funcall(#<subr call-interactively> smex nil nil)
  (with-no-warnings (funcall ad--addoit-function function record-flag keys))
  (setq ad-return-value (with-no-warnings (funcall ad--addoit-function function record-flag keys)))
  (let ((ido-ubiquitous-next-override (ido-ubiquitous-get-command-override function))) (setq ad-return-value (with-no-warnings (funcall ad--addoit-function function record-flag keys))))
  (ido-ubiquitous-with-override (ido-ubiquitous-get-command-override function) (setq ad-return-value (with-no-warnings (funcall ad--addoit-function function record-flag keys))))
  (let (ad-return-value) (ido-ubiquitous-with-override (ido-ubiquitous-get-command-override function) (setq ad-return-value (with-no-warnings (funcall ad--addoit-function function record-flag keys)))) ad-return-value)
  ad-Advice-call-interactively(#<subr call-interactively> smex nil nil)
  apply(ad-Advice-call-interactively #<subr call-interactively> (smex nil nil))
  call-interactively(smex nil nil)
  command-execute(smex)

[Malabarba]

This may be a long shot, but could you disable ido-ubiquitous and smex and try again?

[dobladez]

I'm using the exact same versions of all (except I'm on Linux) and experience the same symptoms.

Try: (setq nrepl-log-messages nil)

I've run Emacs' profiler and this is what I found:

- nrepl-client-filter                                          144560  92%
 - nrepl--dispatch-response                                    144345  92%
  - nrepl-log-message                                          144297  92%
   - nrepl--pp                                                 144289  92%
    - nrepl--pp                                                144289  92%
     - nrepl--pp                                               138195  88%
      - nrepl--pp                                              138164  88%
       - nrepl--pp                                             137768  88%
        - nrepl--pp                                            137344  88%
         - pp                                                  137324  88%
          - pp-to-string                                       137200  88%
           - byte-code                                         136959  87%
            - kill-buffer                                      136814  87%
             - wg-auto-dissociate-buffer-hook                  135832  87%
              - if                                             135832  87%
               - progn                                         135832  87%
                - let                                          135824  87%
                 - if                                          135752  87%
                  - progn                                      135752  87%
                   - wg-workgroup-dissociate-bufobj             135748  87%
                    - let*                                     135748  87%
                     - wg-bufobj-uid-or-add                    135684  87%
                      - cond                                   135680  87%
                       - wg-buffer-uid-or-add                  135680  87%
                        - or                                   135680  87%
                         - wg-add-buffer-to-buf-list             135676  87%
...

Seems like pp creates a temporary buffer, thus causing a lot of buffer "churn". Since workgroups-mode has a hook there (not a cheap one, it seems), it slows everything to a crawl.

So, for me, disabling nrepl logging ( (setq nrepl-log-messages nil)) works around the problem.

[Malabarba]

Interesting. @mrrodriguez do you use workgroup?

[mrrodriguez]

I do not use workgroup. I tried (setq nrepl-log-messages nil) anyways, and it didn't seem to make any difference.

I also tried disabling ido-ubiquitous and I didn't see a difference. I'm not sure about how to disable smex. It just seems to be a function to me, not a mode.

I think the hanging may be a little less when emacs has just been started. It seems that over time, things gradually get slower and lock up more often.

[dobladez]

@mrrodriguez I'd suggest to run the profiler, it's really easy:

1. M-x profiler-start
2. Try your thing (connect to nrepl)
3. M-x profiler-repot. This will open a buffer with the profiling information. It should give you pointers to which functions are causing the problem

I hope this helps.

[mrrodriguez]

@dobladez thanks for the advice. This has helped me get some more information I believe.
These lock ups I describe here are not only on cider-connect. They seem to happen fairly regularly throughout my interaction with the REPL. I profiled a few times during a locking pause (lasts like 3-10 seconds) and here is what I'm seeing:

+ ...                                                             773  77%
- nrepl-client-filter                                             196  19%
 - funcall                                                        173  17%
  - #<compiled 0x419e4e09>                                        173  17%
   - run-hook-with-args                                           173  17%
    - cider-repl--state-handler                                   173  17%
     - funcall                                                    173  17%
      - #<compiled 0x446e5391>                                    172  17%
       - cider-refresh-dynamic-font-lock                          168  16%
        - cider--compile-font-lock-keywords                       165  16%
         - regexp-opt                                             132  13%
          - regexp-opt-group                                      114  11%
           - regexp-opt-group                                     105  10%
            - regexp-opt-group                                    101  10%
             - regexp-opt-group                                    96   9%
              - regexp-opt-group                                   96   9%
               - regexp-opt-group                                  95   9%
                - regexp-opt-group                                 86   8%
                 - regexp-opt-group                                82   8%
                  - regexp-opt-group                               80   8%
                   - regexp-opt-group                              76   7%
                    - regexp-opt-group                             74   7%
                     - regexp-opt-group                            72   7%
                      - regexp-opt-group                           71   7%
                       - regexp-opt-group                          64   6%
                        - regexp-opt-group                         47   4%
                           regexp-opt-group                        24   2%
                           mapcar                                  21   2%
                        + mapcar                                   17   1%
                       + mapcar                                     5   0%
                      + mapcar                                      1   0%
                     + mapcar                                       2   0%
                    + mapcar                                        1   0%
                   + mapcar                                         4   0%
                    mapcar                                          1   0%
                 + mapcar                                           4   0%
                + mapcar                                            6   0%
                 mapcar                                             1   0%
             + mapcar                                               4   0%
            + mapcar                                                3   0%
            delete-dups                                            17   1%
            sort                                                    1   0%
         + #<compiled 0x4561de6d>                                  31   3%
        + cider-resolve-ns-symbols                                  3   0%
       + cider-current-ns                                           2   0%
       + cider-resolve--get-in                                      1   0%
 + nrepl--dispatch-response                                        22   2%
+ command-execute                                                  12   1%
+ linum-update-current                                              7   0%
+ timer-event-handler                                               3   0%
+ redisplay_internal (C function)                                   1   0%

I'm posting here to see if this is useful to anyone on the issue.

[Malabarba]

Thanks for all the info @mrrodriguez. Looks like it's the dynamic-font-lock feature.
Try setting cider-font-lock-dynamically to nil and see if it improves the situation for you.

If that's the case, I'll have to see how we can optimize that stuff. It's going to be hard though, given that most of the work seems to be spent on regexp-opt. Frankly, I'm surprised that function is not written in C. =/

[mrrodriguez]

@Malabarba I set cider-font-lock-dynamically to nil and I believe most of my locking has went away.
I haven't seen any significant lock up since I did this.

That is unfortunate that this seems to bottom-out on regexp-opt... maybe there is a way to avoid calling it as much or something. However, I have no expertise in that area right now.

What am I losing by now having cider-font-lock-dynamically set anymore? Does the font colors not update when I make namespace changes or something?

[bbatsov]

I do wonder why only some people are experiencing those lockups, though. Guess it has to do with the size of the buffers you're working with.

[bbatsov]

@Malabarba Will you be able to take a look at this? It's pretty much the only thing I'd like us to fix before rolling out the new version.

[Malabarba]

@mrrodriguez Yes. What you lose by disabling it is that the color won't update. You only have the static font-locking that has always been available in clojure-mode (which isn't that bad TBH).

I don't think I'll have time to look at this for now, but we can leave it open. The oportunities for optimization seem to be the following:

• Change the response from the middleware to be sorted.
• Optimize cider--compile-font-lock-keywords (maybe by moving it to the clojure side).
• Somehow reimplement our own regexp-opt (maybe by moving it to the clojure side).

[bbatsov]

OK, thanks for the update!

[ptaoussanis]

Just a heads-up that cider-font-lock-dynamically appears to have a dramatic effect on the performance of Cider 0.12.0 on my machine.

Since upgrading to 0.12.0, Cider had become mostly unusable for me. Initial performance was significantly slower than before, and would continue to deteriorate until I'd eventually reboot Emacs after an hour or two of use.

Even managed to get Emacs to entirely lock up OSX a few times, had to do a hard power-off.

Disabling cider-font-lock-dynamically has had an immediate, noticeable positive effect. Cursor movement, etc. is far less laggy. And so far seems to be no performance deterioration over time.

I'll note that I work with some particularly large projects; seems likely that that may be a contributing factor?

[bbatsov]

I don't have time to debug/profile this myself right now and @Malabarba is also busy. Maybe we should just disable it by default for the next release?

[Malabarba]

I guess so. =/

[ckoparkar]

I'd like to try this. Not sure if I'll get anywhere before the release however. I'll ask you guys if I need any help :-)
Is there any specific project to check the the effect of the optimizations ? The size of most of the projects that I work with is relatively small, so the lag is not that bad.

[eulerwang]

I have struggled in this problem a few weeks ; now I have known why I have this problem . I am new to emacs , so I download purcell's emacs config ; I suspect this config result in this problem , because Today I change to prelude's emacs config , I completely have not this problem . hope this will help .

[bbatsov]

Hmm, that's interesting. Prelude definitely doesn't disable dynamic font-locking... Perhaps you experienced some other problem?

[eulerwang]

yes ; the error fly check is off ;the dynamic promoting function is off.

[amoe]

I was having this problem for a long time, maybe 4 or 5 months, but didn't get time to investigate it until a week or so ago, despite how painful it was. The problem is exactly as described by @mrrodriguez above. I was working with largish projects (>50 ns, >5000 LOC etc). Anyway -- setting nrepl-log-messages to nil did indeed fix it. I also eliminated the other variable settings: cider-font-lock-dynamically did not affect the lag, and neither did the presence of eldoc. This problem happens for me when using both cider-jack-in and cider-connect.

;; CIDER 0.13.0 (California), nREPL 0.2.12
;; Clojure 1.8.0, Java 1.8.0_102

This is Emacs 24.5.1 on Debian unstable.

[aiba]

@amoe thank you! This made my day. I am also working on a large codebase (upwards of 35k LOC, I am embarrassed to admit) and this freeze was so annoying.

Can confirm, (setq nrepl-log-messages nil) fixed it.

GNU Emacs 25.1.1 (x86_64-apple-darwin16.0.0, Carbon Version 157 AppKit 1504)
CIDER 0.14.0snapshot (package: 20160914.2335)
Clojure 1.8.0, Java 1.8.0_102

[bbatsov]

I can disable this by default, but it would still be useful if you can share some evaluation that causes this so we can debug it. There's always some overhead from the logging, but it shouldn't be huge...

[amoe]

Here's a giant backtrace from the first hang after cider-jack-in initially showed the REPL welcome screen.

https://gist.github.com/amoe/6164e9bd6cb2b0db7b05e6ef193e1d6b

[Malabarba]

@amoe Looks like the culprit (at least in your case) is fci. That package is seems to be advising delete-char, which is not something I would generally recommend (given how it's a very basic emacs function).

[bbatsov]

Indeed - the stacktrace clearly indicates the error doesn't happen in CIDER itself.

[aiba]

In case it helps, I tried to use toggle-debug-on-quit to get a stacktrace during the hang, but all that did was produce a buffer *Backtrace* with:

Debugger entered--Lisp error: (quit)
  redisplay_internal\ \(C\ function\)()

Although I typed C-g while it was hung, the backtrace didn't appear until after the hang, so I'm wondering if the C-g didn't get processed until after the hang.

Then I tried profiler-start followed by cider-connect followed by profiler-report and got this report: https://gist.github.com/aiba/68683da3a1ab8898a89e6dab9d64347c

There's another time it would hang, which is after running (clojure.tools.namespace.repl/refresh). I did a profile of that and got this report: https://gist.github.com/aiba/91d330df7e98f25d23ab9e75cfb0d6eb

Both hangs (on cider-connect and on (clojure.tools.namespace.repl/refresh)) go away when nrepl-log-messages is nil.

Hope this is helpful. I'm happy to run any other commands that could be useful toward tracking this down as well.

[bbatsov]

That's very helpful indeed. According to the profile data the nREPL message logging is super slow, which is probably something to be expected for big requests/responses.

[bbatsov]

I've disabled the message logging by default in light of the performance issue and I'll file a separate issue about it.

[bbatsov]

On a related note how many of you are having performance issues with the dynamic font-locking functionality?

[mrrodriguez]

I mentioned at #1758 (comment) that disabling dynamic font locking is what fixed the locking issues for me. So I would say that was where my problem was coming from.

[bbatsov]

Yeah, I saw this - but it seems most people here had issues with the nrepl-log, not with the dynamic font-locking. That's why I asked. :-)

[mrrodriguez]

It's odd to me that I didn't have to do anything with logging to fix it. Just the dynamic font locking. Perhaps just different issues that are environment dependent.

[vspinu]

Those who reported hang on logging, did you notice what was the message that caused the hang? What middleware could cause a massive log during startup?

For the record, this is a programatic way to invoke the profiler for testing the logger:

(benchmark-run 1
  (let ((nrepl-log-messages t))
    (profiler-start 'cpu)
    (dotimes (i 500)
      ;; (cider-sync-request:inspect-expr "10" (cider-current-ns) "32")
      ;; (cider-eldoc-info "take")
      (nrepl-sync-request:describe (cider-current-connection)))
    (profiler-report)
    (profiler-stop)))

[aiba]

Regarding middleware, in my case I am running the nrepl server with:

(clojure.tools.nrepl.server/start-server
   :bind "0.0.0.0"
   :port p
   :handler (-> cider.nrepl/cider-nrepl-handler
                (refactor-nrepl.middleware/wrap-refactor)))

Regarding dynamic-font-locking, I tried disabling it but didn't notice any difference in the hang-on-connect behavior. My other (non-data-supported) impression was that it improved the editing speed of some long hairy functions that I never should have written in the first place :-). Also the syntax highlighting seemed significantly better with dynamic-font-locking, so I've been keeping it on and don't have any complaints.

[bbatsov]

Guess we can close this ticket now.