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!