Cider: 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 - https://github.com/clojure-emacs/cider-nrepl/issues/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 [email protected] 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
https://github.com/clojure-emacs/cider/issues/1717#issuecomment-214465960

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?

[kovrik]

what happens in the two different JVMs?

See StackOverflow link in my message above :)

[Malabarba]

@kovrik

1. java -cp $MY_CIDER_NREPL_CP clojure.main
   This is mostly irrelevant. Adding CIDER to the classpath doesn't load it.
2. lein repl (+ nrepl)
   This looks surprisingly slow, but the only thing we can do to improve it is to add support for socket-repl (thus droping nrepl), which noone has volunteered for.
3. lein repl (+ nrepl) + cider-nrepl
   This is the one we might be able to optimize further.
4. cider-jack-in
   This really should not be slower than the previous one. Did you remove cider-nrepl from your profiles/project.clj before doing jack-in? If this is really the case, then we should figure out how to fix this.

[kovrik]

Results of experiments:
https://github.com/kovrik/cider-diet

Can anybody check if it works as expected? Or I broke something?

Probably, we can try to polish it and create new "project type" in cider (for those cases when you need lightweight REPL).

[puredanger]

In case it helps anyone, I recorded the results of some of my own explorations at http://dev.clojure.org/display/design/Improving+Clojure+Start+Time - I had a timeboxed period of time to look at this, so this is not done and certainly more things I'd like to look at / investigate in the future. I wasn't looking at cider at all but really at lein / nrepl times, which has a lot of overlap to what you're seeing I think.

[Malabarba]

@puredanger Thanks for all the info. I'm curious about direct-linking. If we compile cider with direct linking, should we (in theory) see a performance increase when starting a REPL in a project that doesn't have direct-linking enabled?

[puredanger]

@Malabarba If the slowdown is in cider itself and the function invocation is a cause of the slowness, then yes. However, I think it's unlikely that either of those is true, so in practice, my guess would be that you'd see little effect.

[arichiardi]

Just wanted to add a quick test I did today: thanks to @micha's boot-cp I can generate the classpath and then launch the repl using java. The following is the testing script (the project has 30-35 deps):

#!/bin/bash
boot with-cp -w; echo '(System/exit 0)' | java -cp src:$(cat cp) clojure.main

And this is the result on my machine:

real    0m4.909s
user    0m8.643s
sys    0m0.356s

The java command is almost instantaneous, so it looks like the biggest part is to generated the classpath. My machine is not so fast ;)

[Malabarba]

@arichiardi, I don't understand. If you time the execution of that script, won't that include the time taken to generate the class path? Isn't that what the boot with-cp -wpart is doing?
If so, how can you conclude that generating the class path is the slow part?

[arichiardi]

@Malabarba mmm, maybe something is off :smile: but I tried the script with a generated classpath (reading from a file) and java -cp is of course super quick...also tried this...probably I should have specified that part too but I was on mobile and did not take the necessary time...

[kovrik]

Generating classpath should not be slow (and I believe it is not).
There should be no significant difference between java -cp .. with pre-generated classpath and without it.

Also, as https://github.com/kovrik/cider-diet shows (at least I hope so) is that starting bare nREPL server does not take much time either (it is not super fast, but yeah, it is acceptable).

Which means that it is lein/boot (and then cider) who are actually slow.
Loading middleware is fast (cider-diet does load it too).
So, the slow thing is what lein/boot/cider do besides starting nREPL (whatever that is).

At least that is how I see it.

[arichiardi]

Mmm, I basically used boot for writing the classpath to a file and then do java -cp $(cat file) and of course the latter is quite fast compared to the time boot takes to spin up a JVM and resolve the classpath using aether and shutdown.

Note that I used cider-diet like this as well and it is still way faster then a normal lein/boot Repl.

At this point profiling with visualvm would clear up the situation...

[Malabarba]

I think java -cp $(cat file) doesn't do much. You'd have to call the actual function that starts a repl, wouldn't you? Otherwise only clojure.main would be loaded.

[Malabarba]

@kovrik What does your cider-diet actually do? Is it just a jar that bypasses lein/boot (by starting a REPL with all the middleware attached)?

[arichiardi]

@Malabarba yes it is exactly that, and launches nrepl server...

[arichiardi]

Class loading is inherently slow as Alex's findings show, so it makes sense that if you load classes from boot and lein (together with core + cider) the time goes up.

For example another thing I notice with cider-diet is that the startup is very fast but it brings you to user only. As soon as I switch to any other app ns (in particular dev, where I require a lot of stuff), there is another penalty due to another batch of class loading.

[puredanger]

@arichiardi I'd be slightly more careful in words there. I didn't find that classloading is inherently slow (I think it's actually quite fast). I found that start time is correlated with the number of vars loaded (which is also correlated with classloading). Several things contribute to the per-var cost and classloading is only one component (and I suspect not the dominant one).

[arichiardi]

@puredanger true, sorry about that, it is probably not class loading but rather var loading...again, I will need some profiling session before saying something more accurate :+1:

[kovrik]

@Malabarba

What does your cider-diet actually do? Is it just a jar that bypasses lein/boot (by starting a REPL with all the middleware attached)?

Correct.

Took a quick look at profiling snapshot (it was lein repl in cider-nrepl project with :repl-options {:init (System/exit 0)} in project.clj).

Results:
https://gist.github.com/kovrik/57b46185c96e29ea9e117a7ffc933c8a

[arichiardi]

Nice! So as expected the load functions are taking the most of the time, at this point it would be great to know the load of what exactly. This confirms what Alex was saying, aka that var loading is the heavy part.

[Malabarba]

Could we trim unused vars from cider-nrepl? I'm sure all vars directly in cider are used, but we also inline dependencies, so some of those deps could have unused stuff.

[cursive-ide]

Generating classpath should not be slow (and I believe it is not).

Generating the classpath can definitely be slow with Lein, since that requires all plugins and middleware to be loaded and all dependencies to be resolved. If you have all deps cached locally the resolution is quite quick, but if you have any snapshot repos it can take a really long time.

I actually considered caching the REPL classpath along with the fully resolved project map for a given project config in Cursive, since it would definitely improve REPL start time a lot. However it's difficult (or perhaps impossible) to work out all the sources lein uses for its dependency calculation, and if any of them are missed then the caching is incorrect and will lead to frustration.

[kovrik]

If you have all deps cached locally the resolution is quite quick

By "_cached_" you mean "_have deps in a local Maven repo_" or "_have pre-generated and cached classpath_"?

And why dependency resolution is slow in Lein?
Is it caused by transitive dependencies?
Or it is just because the way it resolves them is not optimized?

Tried mvn dependency:list on a huuuuuge project (45 modules, tons of deps) - it took 1 min for the first run (mostly downloading deps), and then 8.5s for all other runs.

On cider-nrepl project mvn dependency:list takes 6s for the first run (it downloads deps) and after that it takes just 2s.
lein repl still takes ~20s.

And cider-nrepl dependency tree is tiny:

• 88 deps
• 26 duplicates
• 9 conflicts
• 16 deps with compile or provided scope

[cursive-ide]

Sorry, by cached I meant "your deps are in your local Maven repo".

I haven't broken it down, but lein definitely takes a long time to calculate the classpath. Again, this involves loading all middleware & plugins and does a surprising amount of work - I haven't profiled it to see how much is resolution and how much is lein doing its thing.

Previously, Cursive used to calculate the REPL classpath on the EDT, which would cause the UI to lock up. I had to fix that (which was surprisingly hard, due to both lein and IntelliJ), primarily because of the snapshot repo issue but also because even under normal circumstances it takes a noticeable amount of time. Separating it out means that I can now run it with a progress meter, and people immediately started to complain about how long it took as soon as they saw it happening. I don't think it takes any longer now, it's just visible.

[kovrik]

Sorry, by cached I meant "your deps are in your local Maven repo".

But the problem is that at least for me it still takes ~20 seconds to start lein repl even if all dependencies are in my local Maven repo.
That is why I think it's weird.

Again, this involves loading all middleware & plugins and does a surprising amount of work

I'm loading all middleware in cider-diet (see messages above) and it takes just 4 seconds to start JVM, load everything up, start nREPL server and connect to it.

Maybe I am missing something, but I don't understand how dependency resolution may take so much time in lein repl (let's ignore situations when it has to download all deps into local repo first).

For Maven it took 2 seconds to resolve all deps and print a nice dependency tree.
If it takes 10 times more for Lein, then this is bizarre.

And it seems that we don't have consensus on _What is causing lein repl to take so long to start_.

Opinions are:

• var loading
• dependency resolution
• ???

[puredanger]

In my investigations, I have not found that dep resolution is the slow part (unless you have a totally empty local Maven cache, which I'm going to say is not an interesting thing to optimize as it's rare). If that is the slow part, then you should see all that time go away when using lein fast trampoline, so that's a useful thing to compare to get an idea.

When startup takes 10s of seconds it is almost always to compile and load 1000s of vars, either from dependencies or from the application itself. This could also be from the tooling (nrepl+middlewares), although I have not found that to be a significant factor in projects I've looked at.

Generally AOT compiling the dependencies or application code or tooling (particularly if direct linked) will dramatically reduce those times. If using AOT+direct linking, the work Rich has done on lazy vars also makes another incremental improvement in avoiding the eager load of vars you don't need.

However, there are a lot of downsides with doing this pre-compilation. First, you are binding to Clojure and downstream dependencies early, rather than late, making it more common to encounter versioning problems and conflicts. Second, if you compiling a library you have to decide whether to release both a source and an AOT version of your library - doing both is not well-supported in the tools for either production or consumption. And there are a number of tricky compilation problems resulting from mixing AOT and non-AOT compiled code with interdependencies and the transitive nature of AOT exacerbates this. Finally, AOT compiling your own project code both introduces more of those problems and makes dynamic REPL-based development more problematic.

So the question is - what can be done to improve non-AOT load time in large projects and/or projects with many dependencies? For me, I think that's the use case that is most hurting people during dev time.

Making reading or compilation faster (certainly possible) would be wins for everyone everywhere so those are good avenues (but also offer diminishing returns after the first batch of work). Caching compilation (like is done in CLJS) is interesting and something worth looking at, particularly if coupled with direct linking and lazy vars. The compilation cache would let you skip a huge chunk of largely repetitive work and lazy vars would allow you to skip a reasonable chunk of the var loading time. Lazy vars are not necessarily great for long-running production compiled apps but might be perfect for something like this. Parallel compilation/load is another thing to think about, but Clojure namespace loading is currently not well-suited for this.

That's the kind of stuff we're looking at in core. Anything that can be done to defer loading of things in either the tooling or the project under work or dependencies on startup will only help.

[Malabarba]

First, you are binding to Clojure and downstream dependencies early, rather than late, making it more common to encounter versioning problems and conflicts.

Yes, AOT compiling Clojure is probably not something we should do. However, cider does inline all of its dependencies (besides Clojure) so that should prevent conflicts should we decide to AOT them (IIUC).

[arichiardi]

I came up with a boot task for starting a repl with cider-diet. It follows the conventions of my project for now but it is not difficult to adapt (hard-coding port and paths for instance).

It greatly improves the startup time even if it still runs inside boot (two VMs are active at the same time). For sure executing it like here was faster but I am ok with this at the moment.

I will test it further in my projects and see if there is any flaw in the approach.

[alexander-yakushev]

So today I grabbed a profiler and did some investigation. I profiled launching the REPL with boot, using the command:

boot cider repl -s

(cider is a Boot task that applies CIDER dependency and middleware).

Turned out there are a few offending middlewares:

• format — accounts for ~30% of CIDER loading time. Transitively the hog that takes the most time to load is clj-rewrite dependency.
• apropos — ~21% of the time. Transitively caused mostly by fipp.
• complete — ~13%. Comes mostly from loading compliment.
• debug — 8%.

Cast @bbatsov, @Malabarba

[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

```$ time lein with-profile new repl < /dev/null
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" [e-mail] 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
https://github.com/clojure-emacs/cider/issues/1717#issuecomment-317277506,
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. :bowing_man: @vspinu!