high nrepl/cider latency

[j0ni]

I follow the cider HEAD via melpa, and update daily.

Sometime in the last week I have noticed a sudden increase in latency, both during the connection setup when I make my connection to a running nrepl server, and when using the repl interactively in emacs.

It now takes more than 15 seconds now between nREPL: Direct connection established and Connected., during which emacs hangs. After that, every interaction with cider's repl takes a second or two to return.

Now I have switched back to 0.9.1 (need to work) and everything is snappy and quick again.

What additional information would help debug this?

[Malabarba]

What additional information would help debug this?

1. M-x toggle-debug-on-quit
2. Evaluate something in the repl
3. While it's hanged, hit C-g.
4. Paste the backtrace here.

[Malabarba]

FTR, I don't experience any hangs. But I do experience a lag after the repl displays the evaluation result but before it prints the new prompt. There's no hang, but it takes about 0.3 sec to display the new prompt.

I've tracked this issue down to the track-state middleware, and it might be related to your problem.

[claj]

I see a similar delay, and it's several seconds long (it's a quite large project). I cannot find any backtrace with C-g.

CIDER 0.10.0snapshot (package: 20150913.1602) (Java 1.8.0_60, Clojure 1.8.0-alpha5, nREPL 0.2.10)

[Malabarba]

Once https://github.com/clojure-emacs/cider-nrepl/issues/252 has been merged, I'm thinking we'll have to add an option to disable the state tracker for those with really large projects.

Does anyone know of a way to determine which namespaces come from deps and which are part of the project? That would help a lot.

[expez]

You can use clojure.tools.namespace.find/find-namespaces-in-dir on the project root.

[Malabarba]

@claj Could you check something for me? What do you get (how many ms) if you run the following?

(time (clojure.tools.namespace.find/find-namespaces-in-dir (java.io.File. "/path/to/project/src")))

[claj]

@Malabarba, thanks for looking into this!

(time (clojure.tools.namespace.find/find-namespaces-in-dir (java.io.File. "MY-PROJECT_PATH"))) "Elapsed time: 1174.691963 msecs"

Actually, I think clojure-1.8.0-alpha{4,5} takes quite a while to start, even in $lein repl. I'm not sure cider is to blame.

[expez]

Jeez. I just ran the same query on cider-nrepl. With all the deps inlined it's a total of 150 namespace and it took 9ms to fetch their names.

refactor-nrepl is somewhat slower at 20.6ms for 68 namespaces (not including inlined deps but quite a few test resources which are clojure files too).

[Malabarba]

@expez that's pretty fast. It takes about 100ms for me on the cider-nrepl repo, and that only includes the cider namespaces directly, no dependencies or anything.

[expez]

You guys have SSDs right?

Anyway, @Malabarba the fact that this is too slow shouldn't really be a problem. We don't have to do this synchronously or all the time. We can figure out which namespaces are dependencies once, in the background on startup, and keep the answer around for the duration of the session.

[Malabarba]

@expez

You guys have SSDs right?

Well that explains it.

Anyway, @Malabarba the fact that this is too slow shouldn't really be a problem. We don't have to do this synchronously or all the time. We can figure out which namespaces are dependencies once, in the background on startup, and keep the answer around for the duration of the session.

I thought about that, but I'm not sure it would work. Isn't it possible that some dependencies are not loaded initially, but become loaded during the session (after the user requires them)?

Then we would end up thinking these deps are new user namespaces.

[expez]

Isn't it possible that some dependencies are not loaded initially, but become loaded during the session (after the user requires them)?

Absolutely. Thankfully tools.namespace has facilities for finding all namespaces on the classpath. If we limit ourselves to looking inside jar files, with find/find-namespaces-in-jar, I think we should be good.

[j0ni]

@Malabarba your description of the pause before displaying the next repl prompt fits my second case. There is also the long pause during connection setup.

When I pressed C-g during the repl pause you mentioned, I got an empty *Backtrace* buffer.

When I pressed C-g during a connection setup pause, I got the following trace:

Debugger entered--Lisp error: (quit)
  accept-process-output(nil 0.01)
  nrepl-send-sync-request(("op" "eval" "session" "52b5bad3-f3bd-446e-a9f2-4ed5dc5acb32" "code" "(str *ns*)" "id" "4") #<buffer *cider-repl localhost:6005*>)
  nrepl-sync-request:eval("(str *ns*)" #<buffer *cider-repl localhost:6005*> "52b5bad3-f3bd-446e-a9f2-4ed5dc5acb32" nil)
  cider-nrepl-sync-request:eval("(str *ns*)")
  cider-repl-set-initial-ns(#<buffer *cider-repl localhost:6005*>)
  cider-repl-init(#<buffer *cider-repl localhost:6005*>)
  cider--connected-handler()
  run-hooks(nrepl-connected-hook)
  nrepl-start-client-process("localhost" "6005")
  cider-connect("localhost" "6005")
  #<subr call-interactively>(cider-connect record nil)
  ad-Advice-call-interactively(#<subr call-interactively> cider-connect record nil)
  apply(ad-Advice-call-interactively #<subr call-interactively> (cider-connect record nil))
  call-interactively(cider-connect record nil)
  command-execute(cider-connect record)
  execute-extended-command(nil "cider-connect")
  smex-read-and-run(("toggle-debug-on-quit" "cider-jack-in" "disable-theme" "linum-mode" "cd" "5x5" "arp" "cider-quit" "git-gutter:toggle" "set-mode-line-box" "ag" "ack" "dbx" "dig" "erc" "ert" "eww" "ftp" "gdb" "irc" "jdb" "man" "mpc" "pdb" "pwd" "rsh" "sdb" "xdb" "calc" "deft" "diff" "dirs" "ffap" "ffip" "gnus" "grep" "help" "ielm" "info" "life" "mail" "mpuz" "ping" "pong" "smex" "talk" "term" "undo" "yank" "zone" ...))
  smex()
  #<subr call-interactively>(smex nil nil)
  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]

PR https://github.com/clojure-emacs/cider-nrepl/pull/253 should improve this situation considerably. Besides some low-level performance improvements, it implements @expez's idea of skipping namespaces from jar files.

If the project src directory is extremely large, there might still be some lag (I eagerly await feedback on this once that PR gets merged). But even in this case the PR should at least bring a noticeable improvement, since (I think) projects are usually composed of more deps than sources.

When I pressed C-g during a connection setup pause, I got the following trace:

Thanks @j0ni, this seems to confirm what I thought.

[Malabarba]

@j0ni Let me know if the lag is any better after you upgrade to the latest snapshot.

[j0ni]

@Malabarba thanks - any idea how long it will be before the snapshot makes it to clojars?

[bbatsov]

It has been there for a few hours now.

On Tuesday, September 15, 2015, J Irving notifications@github.com wrote:

@Malabarba https://github.com/Malabarba thanks - any idea how long it will be before the snapshot makes it to clojars?

— Reply to this email directly or view it on GitHub https://github.com/clojure-emacs/cider/issues/1320#issuecomment-140395957 .

[expez]

@j0ni you can pull in a new snapshot forcefully by doing lein -U repl

[j0ni]

OK, finally got a chance to test this. The first pause, when setting up the nrepl connection, has been reduced to 8 or 9 seconds from 15+. There's no perceptible (to me) change in the lag using the repl.

[Malabarba]

Good, that's progress. :) Now I feel that we're computing as little data as possible, so the next step will be sending the state information on its own message, instead of associng on the done message. This means nothing will be held back while the data is computed, and both lags should be gone.