Do some profiling to find out why it takes so long to start a REPL

[Malabarba]

Currently, when starting a REPL in a project with the cider-nrepl middleware/plugin, it takes on the order of 30 seconds to go from 0 to REPL.
Even though that's not a huge deal breaker, it does get very annoying under some workflows.

What's worse, I've found that it sort of pushes me into some specific habits, like never restarting a REPL, or preferring to use the command-line to run tests if I don't have an open REPL.
While such habits aren't obviously bad, they aren't obviously good either, and I don't think it's good that CIDER incentivates them.

---

It would be great if we had some profiling data on what takes so long. If it turns out to be unavoidable, then so be it. But maybe it's one specific dependency we could ditch. Or maybe it's a namespace that's doing something silly.

[edipofederle]

Hi @Malabarba

Maybe we can use a benchmark here. I found this http://doc.endlessparentheses.com/Fun/benchmark.

If you think this is one possible way, I will try look at it and see what I can discover.

[bbatsov]

Related ticket - clojure-emacs/cider-nrepl#218

I'm reasonably sure that the inlined deps make it so slow to start a CIDER REPL, but I can't find our discussion on the subject. Before introducing mranderson the REPL started 3-4 times if I remember correctly.

[Malabarba]

Unfortunately that's not going to help. We need to profile the Clojure side of things (the cider-nrepl middleware). So this is strictly a Java/Clojure job.

[edipofederle]

Truth. Well, anyway I will try to look that way you commented and try to find something

[Malabarba]

I'm reasonably sure that the inlined deps make it so slow to start a CIDER REPL, but I can't find our discussion on the subject. Before introducing mranderson the REPL started 3-4 times if I remember correctly.

In theory, there's no reason why injecting deps would make things slower. After all, it doesn't change the number of namespaces that need to be loaded on a blank project.
If that's really the cause, then there's a good chance it's something we can optimize.

BTW, do we AOT compile cider-nrepl?

[expez]

BTW, do we AOT compile cider-nrepl?

AOT compilation is used very rarely. It has some weird edge-cases and there's no real benefit (other than obfuscating proprietary source code). When the JVM starts a clojure app it spends a trivial amount of time compiling stuff.

[bbatsov]

In theory, there's no reason why injecting deps would make things slower. After all, it doesn't change the number of namespaces that need to be loaded on a blank project.
If that's really the cause, then there's a good chance it's something we can optimize.

Guess someone can see what's the boot time now with a clean cider-nrepl and one built with mranderson, so we would have a starting point. We never measured even this - I just remember people started complaining about the slow boot immediately after we started using mranderson.

[Malabarba]

Guess someone can see what's the boot time now with a clean cider-nrepl and one built with mranderson, so we would have a starting point.

I just measured 19 sec on both cases. So looks like inlining is not the cause.

[Malabarba]

AOT compilation reduces that by about 4 seconds. A bit better, but still noticeably slow.

[expez]

If you just do lein repl with an empty profiles.clj and add deps you'll notice a linear increase in startup time.

I'm guessing the difference between now and then is that you're now working on projects with more dependencies ;)

[Malabarba]

Well, I'm testing this on a blank project. Besides, project dependencies usually don't add startup time since they're not loaded at startup. However, I just realised that about 6 sec of my benchmark were coming from refactor-nrepl auto-injection.

Here's a rough breakdown with only cider-nrepl:

| Version 0.X.0 | time |
|---------------+------|
|             6 |  4.9 |
|             7 |  8.9 |
|             8 |  8.9 |
|             9 |  9.9 |
|            10 | 10.4 |
|            11 | 11.6 |
|            12 | 12.3 |

Looks like we gained a good 4 seconds on version 0.7. Is that perhaps due to a specific dependency?

[bbatsov]

Guess we should check what we added then.

On Monday, 25 April 2016, Artur Malabarba notifications@github.com wrote:

Well, I'm testing this on a blank project. Besides, project dependencies
usually don't add startup time since they're not loaded at startup.
However, I just realised that about 8 sec of my benchmark were coming from
refactor-nrepl auto-injection.

Here's a rough breakdown with only cider-nrepl:

| Version 0.X.0 | time|
| 6|4.9|
| 7|8.9|
| 8|8.9|
| 9|9.9|
| 10|10.4|
| 11|11.6|
| 12|12.3|

Looks like we gained a good 4 seconds on version 0.7. Is that perhaps due
to a specific dependency?

—
You are receiving this because you commented.
Reply to this email directly or view it on GitHub
#1717 (comment)

Best Regards,
Bozhidar Batsov

http://www.batsov.com

[dpsutton]

What's a good way to look into this?

[bbatsov]

In 0.7 we've added:

• [cljs-tooling "0.1.3"]
• [org.tcrawley/dynapath "0.2.3"]
• [org.clojure/tools.trace "0.7.8"]]

[kovrik]

For me running just lein repl :headless with empty profiles.clj takes ~10 secs to start.

Running lein update-in :dependencies conj ^"[org.clojure/tools.nrepl \^"0.2.12\^"]^" -- update-in :plugins conj ^"[cider/cider-nrepl \^"0.13.0-SNAPSHOT\^"]^" -- repl :headless (command taken from cider-jack-in logs) takes ~30 seconds.

Removing :dependencies part does not affect anything, single :plugins with cider/cider-nrepl adds 20 secs to a startup time.

[kovrik]

Also, tried to do some profiling.
Running cider-jack-in command:

• takes 30 seconds
• involves 5 GCs (at least)
• loads 10k+ classes
• calls at least 12k different methods (some of them invoked 200k+ times)
• tons of those calls are related to PersistentHashMap

Yeah, of course, majority of those method calls/loaded classes are just Clojure runtime classes/methods.

But 5 GCs...

Can anyone point to the best way to start working on that issue?

[Malabarba]

@kovrik Could you post the full reports you for from your profiling? Maybe we can spot some unnecessary loops or something.

[kovrik]

@Malabarba
Yes, will try to clean it up (get rid of useless Clojure runtime stuff) and post it here.

[Malabarba]

Thanks! If possible, also post the raw original in a gist somewhere. It could be useful too.

[kovrik]

Profiling snapshot size is 851 MB. Need some time to review it :)

[Malabarba]

Oh dear 😮

[kovrik]

On Mac it takes ~16 seconds.
If I add something like:

(println "START:" (format "%.0f" (/ (. System (nanoTime)) 1000000000.0)))

into nrepl.clj

And

:repl-options {:init (println "END:" (format "%.0f" (/ (. System (nanoTime)) 1000000000.0)))}

into project.clj,
then it takes ~8 seconds to see "START" message first and 8 more seconds to see "END" message and get working REPL.
On Windows it is ~12-14 seconds for each.
(but not sure if such a "benchmark" is valid or not)

I'm not quite familiar with how cider works, reading sources at the moment, but any help would be appreciated :)

Did a quick look at profiling results:

• it has many file reads
• many load / loadLibrary calls

So, my initial guess would be that it takes so long to just load all dependencies required, do all imports etc. Trying to confirm that.

Is there a way to reduce number of dependencies or not load them all at once, but load them on-demand?

[kovrik]

Also, I see the following message:
Warning: Clojure is excluded, assuming an appropriate fork (Clojure 1.7 or later) is provided.
3(!) times until i see REPL.

The only place I see that message being printed is
https://github.com/clojure-emacs/cider-nrepl/blob/master/src/cider_nrepl/plugin.clj#L45

It starts 2 JVMs, isn't it? But why I see message 3 times. not 2?

[kovrik]

Timings:

command	time	description
java -jar Test	0.1s	JVM startup time is blazing fast. Simple Hello World app starts almost instantly:
java -jar clojure-1.8.0.jar	1-1.3s	Clojure REPL is much slower, but still pretty fast:
java -cp $MY_CIDER_NREPL_CP clojure.main	1-1.3s	Clojure REPL with cider-nrepl's CLASSPATH
lein repl (+ nrepl)	11s	Slow: Ten times slower!
lein repl (+ nrepl) + cider-nrepl	20-24s	SLOWER
cider-jack-in	30-32s	Unbearably SLOW

I would say that we are looking at optimizing last 3 commands (each add ~10 secs).

[expez]

It starts 2 JVMs, isn't it? But why I see message 3 times. not 2?

It starts two?

[kovrik]

It starts two?

lein repl starts 2:

~ λ jps
72112 Jps

~ λ lein repl
nREPL server started on port 51232 on host 127.0.0.1 - nrepl://127.0.0.1:51232
REPL-y 0.3.7, nREPL 0.2.12
Clojure 1.8.0
Java HotSpot(TM) 64-Bit Server VM 1.8.0-b132

~ λ jps
72032 main
71986 main
72119 Jps

(http://stackoverflow.com/questions/27339206/why-does-leiningen-keep-its-own-jvm-running)

[expez]

Ah! Not to derail the thread, but what happens in the two different JVMs?

[expez]

Would removing the require statements in the ns form, in favor of on-demand calls to require, solve this, or is this related to work done eagerly to every lib on the classpath?

[bbatsov]

Hmm, format is a bit of functionality that's not important at all. Probably we should spin it off to some separate middleware or something like this if it causes such a performance hit.

[alexander-yakushev]

I would suggest someone else to experiment with it too. Profiler could be lying. On my machine, dropping format from the list of middleware semi-consistently saves 2-3 seconds (from ~16 seconds to ~13 seconds, this is without refactor-nrepl).

[arichiardi]

@expez it is a nice experiment to try and probably we need to dig in core for the confirmation but probably ns or not, if the require is called it will load the vars in it.

I am not familiar with this in particular, but I was wondering whether there is a way to say: please only load the vars that I use.
Kind of like a refer that only bootstraps that particular var I want.

Selectively loading only the var in a particular execution path maybe can improve things, but probably it has already been done and I am just rambling 😀

[arichiardi]

@alexander-yakushev good job! This is exactly the kind of thing we need to figure out, I will try to confirm your findings.

[ryfow]

Now that @benedekfazekas uploaded a new refactor-nrepl snapshot, I thought I'd post a comparison of startup times before and after some of this delay work. 17ish seconds doesn't exactly feel snappy, but it's a heck of a lot better than 29ish seconds.

$ cat ~/.lein/profiles.clj
{:user {:dependencies [[ryfow/flame-du-jour "0.1.0"]]}
 :new {:plugins [[cider/cider-nrepl "0.15.0"]
                 [refactor-nrepl "2.4.0-SNAPSHOT"]]
       :dependencies [[clojure-complete "0.2.4"]
                      [org.clojure/tools.nrepl "0.2.12"]]}
 :old {:plugins [[cider/cider-nrepl "0.14.0"]
                  [refactor-nrepl "2.3.1"]]
       :dependencies [[clojure-complete "0.2.4"]
                      [org.clojure/tools.nrepl "0.2.12"]]}}

$ time lein with-profile old repl < /dev/null
nREPL server started on port 56678 on host 127.0.0.1 - nrepl://127.0.0.1:56678
REPL-y 0.3.7, nREPL 0.2.12
Clojure 1.8.0
OpenJDK 64-Bit Server VM 1.8.0_131-8u131-b11-0ubuntu1.16.04.2-b11
    Docs: (doc function-name-here)
          (find-doc "part-of-name-here")
  Source: (source function-name-here)
 Javadoc: (javadoc java-object-or-class-here)
    Exit: Control+D or (exit) or (quit)
 Results: Stored in vars *1, *2, *3, an exception in *e

user=> Bye for now!

real    0m29.667s
user    0m13.405s
sys     0m0.407s

nREPL server started on port 51819 on host 127.0.0.1 - nrepl://127.0.0.1:51819
REPL-y 0.3.7, nREPL 0.2.12
Clojure 1.8.0
OpenJDK 64-Bit Server VM 1.8.0_131-8u131-b11-0ubuntu1.16.04.2-b11
    Docs: (doc function-name-here)
          (find-doc "part-of-name-here")
  Source: (source function-name-here)
 Javadoc: (javadoc java-object-or-class-here)
    Exit: Control+D or (exit) or (quit)
 Results: Stored in vars *1, *2, *3, an exception in *e

user=> Bye for now!

real    0m17.707s
user    0m10.671s
sys     0m0.332s

This was run on a crouton chroot of my Samsung Chromebook Pro on a fresh Leiningen project.

[arichiardi]

Lazy loading is a good solution, at EuroClojure we were discussing about it, it changes semantics but if we could load only the var that are effectively used (finer granularity), then startup time would increase for sure. There are many things that I don't know in core for advocating this but I was thinking of throwing it there and it is nice to see that clj-refactor now does that.

[bbatsov]

I guess there are more opportunities for lazy loading as the bulk of the middlewares are not utilized during the boot process. Hopefully the load times could be brought down even more.

[ryfow]

Here's the Current FlameGraph. I generate these with flame-du-jour

Lazy loading cider.middleware.stacktrace, cider.middleware.debug, and refactor-nrepl.s-expressions seem to be the next biggest wins. Those namespaces likely could be lazy-loaded, but it didn't seem to be as simple as using a targeted require/resolve.

[ryfow]

Another interesting thing about that flamegraph is that refactor-nrepl and cider-nrepl both rewrite and load clojure.tools.namespace.parse so that code is getting loaded twice under two different namespace names. I haven't done an exhaustive search, so there may be other duplicated loading.

[benedekfazekas]

yeah that is a fair point

…

On 23 Jul 2017 9:53 p.m., "Ryan Fowler" ***@***.***> wrote: Another interesting thing about that flamegraph is that refactor-nrepl and cider-nrepl both rewrite and load clojure.tools.namespace.parse so that code is getting loaded twice under two different namespace names. I haven't done an exhaustive search, so there may be other duplicated loading. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#1717 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AA9PnlBud4PRCRlXXnNltffqwlQulLDQks5sQ6SggaJpZM4IPFVz> .

[cursive-ide]

As an aside, JetBrains take startup time really seriously. Extensions to IntelliJ are loaded from an IoC container, and the classes aren't even loaded until the functionality is actually required. Could you do something similar, perhaps associate each editor command that uses some nREPL functionality with the namespace of the server-side bit it requires, and ensure that that is loaded when the command is actually executed? I know that nREPL doesn't like dynamic fiddling with middleware, but something like that might be possible.

[kovrik]

Still, I don't quite understand why it takes 32 seconds (just checked it again on my machine) to start it.

Lazy loading is a very nice thing, should make startup much faster (but still, why it takes so long? just because of the number of classes? or there is something else? some computations on startup?).

For example, Wildfly container (which is huge) loads ~331 modules on startup (which takes ~3.5 seconds - quite impressive, I would say), and lazy-loads ~400 other modules.
But there is more: Wildfly also starts services in parallel. And has concurrent class loading. And more.

Can't find nice info on Wildfly 10, but in general it should be pretty much the same as for JBoss AS 7:
http://in.relation.to/2011/07/25/why-isjboss-as-7-so-fast/

So the general idea is:

1. Split monoliths into small, isolated modules.
2. Reduce coupling between modules as much as possible (to make them independent).
3. Mark essential modules to be started eagerly. And make essential modules as small as possible - move all garbage somewhere else.
4. Mark everything else to be started lazily (on-demand).
5. Start all eager AND independent modules in parallel.

Can we do something similar here?

[kovrik]

Also, I've just pushed some changes to https://github.com/kovrik/cider-diet repo (updated dependencies to the latest versions).
It still works and starts very fast.
Please check it out and see if you would like to implement the same approach in cider.

[bbatsov]

Lazy loading is a very nice thing, should make startup much faster (but still, why it takes so long? just because of the number of classes? or there is something else? some computations on startup?).

It's most the number of classed that get loaded right away. The ns rewriting that we're doing for the deps bloats the number of classes a lot, but it's the only way we found to avoid dependency conflicts.

Can we do something similar here?

Apart from off-loading some requires everything else requires changes in the nREPL server itself. Current it doesn't support lazy middleware loading. This shouldn't be hard to do I think, but until the project is taken out of contrib I doubt anyone would won't to work on such a feature.

The only relatively easy thing we can do in the meantime is to try to move most code from the middlewares to some utility libs, so they can be easily loaded when the middleware is used for the first time.

[bbatsov]

Please check it out and see if you would like to implement the same approach in cider.

Looking at the repo's README it's not clear to me what exactly have you done to speed this up and what are the tradeoffs.

[kovrik]

I no longer use Clojure, so I might be wrong or miss something.

Apart from off-loading some requires everything else requires changes in the nREPL server itself.

As far as I remember, nREPL itself was not a bottleneck.
That is basically what I do in cider-diet: just start nREPL server instance + load all dependencies. This operation is very fast (within 3 seconds).

Starting vanilla Clojure REPL is blazing fast (~1 second).

In my particular case the bottleneck is Leiningen.
If I correctly understand how cider works: it determines project type (lein/boot/gradle) and executes the right command for that type. I've always used Leiningen for Clojure projects.

I don't know what Leiningen does on startup (on lein repl in particular), I guess it scans the project, checks all dependencies, downloads missing stuff etc.
But I know that on my machine starting nREPL instance via lein is 8 (!) times slower than starting it manually.

Benchmarks:

REPL command	Time (seconds)	Comment
java -jar clojure-1.8.0.jar	1.11	Plain Clojure REPL
java -jar cider-diet-1.0.1-standalone.jar	3.5	cider-diet nREPL
lein repl	16	Leiningen REPL
lein repl with-profile old	30	Leiningen REPL with cider-nrepl dependencies

[benedekfazekas]

we could give this a try I suppose and provide a var for other cider "plugins" to add their own middleware similar to what we do for the CLI params

[ryfow]

I don't have great plans for taking the next step, but I do have some familiarity with the problem that hasn't been discussed yet. Maybe this will trigger an idea for someone.

There are essentially two types of middleware that I've noticed. These are names I'm making up.

1. "op handlers" handle a specific :op value
2. "handler wrappers" modify the request or response that a different handler does the "op handling" on.

op handlers are clean because you can just deref a delay when you receive the op you're interested in. That's basically what I did with refactor-nrepl. I just delayed loading of middleware that takes time to load. I think it'd be fairly easy to make a consistent delayed pattern for op handlers.

cider-nrepl seems to have more handler wrappers (for example debug and pprint). For those, it seemed cleanest to delay the require of libraries used by the handlers as @bbatsov said. This is hard to do in a consistent way and I think it'd be easy to let slow-loading dependencies creep into your code base over time.

I monkeyed around with a delayed-refer macro, but it stopped being satisfying when I realized that every pprint library in the world names its pprint function pprint. I feel like Clojure is missing a lazy-require feature that declares vars but doesn't spend a bunch of time evalling everything in the namespace until one of the vars is used. I think you could do this with a preprocessor similar to mranderson but it's a non-trivial effort.

[cursive-ide]

I feel like Clojure is missing a lazy-require feature that declares vars but doesn't spend a bunch of time evalling everything in the namespace until one of the vars is used.

I do this for a lot of my Java/Kotlin->Clojure interop, i.e. calling into Clojure from classes defined in Java/Kotlin. The implementation is pretty trivial:

public class DelayedFn implements IFn {

  private final String namespace;
  private final String name;
  private volatile IFn delegate = null;

  public DelayedFn(String namespace, String name) {
    this.namespace = namespace;
    this.name = name;
  }

  @Override
  public Object invoke() {
    return getDelegate().invoke();
  }

  @Override
  public Object invoke(Object o) {
    return getDelegate().invoke(o);
  }

  ... etc etc ...

  private IFn getDelegate() {
    // See https://en.wikipedia.org/wiki/Double-checked_locking#Usage_in_Java
    IFn result = delegate;
    if (result == null) {
      synchronized (this) {
        result = delegate;
        if (result == null) {
          if (!"clojure.core".equals(namespace)) {
            REQUIRE.invoke(asSym(namespace));
          }

          delegate = var(namespace, name);
          result = delegate;
        }
      }
    }
    return result;
  }
}

...where asSym and var come from clojure.java.api.Clojure.

[cursive-ide]

Actually, looking at that code, I think I just saw a bug - it should be doing the TCCL dance to set the right classloader before calling REQUIRE. It's not normally a problem for me because I set Compiler.LOADER, but that's racy if this gets called during initialisation before that is set. For safety, the TCCL should be set in getDelegate() to the classloader you want to use.

I also suspect that this issue no longer warrants the "low hanging fruit" tag :-)

[xiongtx]

I also suspect that this issue no longer warrants the "low hanging fruit" tag :-)

Yeah, no kidding. This is probably the highest (and juiciest!) fruit in the tree!

[bbatsov]

Haha 😆 The idea was that the profiling should be easy, no one thought that the solution of whatever root cause was uncovered would be easy. 😉

[ryfow]

@kovrik's note triggered my memory on LEIN_FAST_TRAMPOLINE. Is there a reason we're not using it? Seems to drop another 5ish seconds off my repl/cider startup time. This is with the same profiles.clj as above.

(xenial)rfowler@localhost:~/foo$ time lein with-profile new repl < /dev/null
nREPL server started on port 34052 on host 127.0.0.1 - nrepl://127.0.0.1:34052
REPL-y 0.3.7, nREPL 0.2.12
Clojure 1.8.0
OpenJDK 64-Bit Server VM 1.8.0_131-8u131-b11-0ubuntu1.16.04.2-b11
    Docs: (doc function-name-here)
          (find-doc "part-of-name-here")
  Source: (source function-name-here)
 Javadoc: (javadoc java-object-or-class-here)
    Exit: Control+D or (exit) or (quit)
 Results: Stored in vars *1, *2, *3, an exception in *e

user=> Bye for now!

real    0m17.808s
user    0m10.438s
sys     0m0.304s

(xenial)rfowler@localhost:~/foo$ time LEIN_FAST_TRAMPOLINE=t lein with-profile new trampoline repl < /dev/null
WARNING: cat already refers to: #'clojure.core/cat in namespace: net.cgrand.parsley.fold, being replaced by: #'net.cgrand.parsley.fold/cat
REPL-y 0.3.5, nREPL 0.2.12
Clojure 1.8.0
OpenJDK 64-Bit Server VM 1.8.0_131-8u131-b11-0ubuntu1.16.04.2-b11
    Docs: (doc function-name-here)
          (find-doc "part-of-name-here")
  Source: (source function-name-here)
 Javadoc: (javadoc java-object-or-class-here)
    Exit: Control+D or (exit) or (quit)
 Results: Stored in vars *1, *2, *3, an exception in *e

user=> Bye for now!

real    0m12.499s
user    0m38.239s
sys     0m0.507s

[xiongtx]

W/ #438 the REPL now loads very quickly. 🙇 @vspinu!