Playing around with time mix, there are a few things that strike me as odd
It seems slow. time mix compile, a second time after nothing changed, takes about 2.4s on my machine (MacPro '09 with 6 core 3.2Ghz Xeon). Elixir 1.11.4 / OTP 23. Is that expected? We have about 300 *.ex files, 50 *.leex, and our mix.lock is 100 line long.
time mix compile is 20% slower on Elixir 1.12.1 / OTP 24: about 2.9s. Is that expected?
The option --no-compile saves about 20% (0.6s). Why? There is no compilation anyways in this test as I’m not modifying any file.
The option --no-app-loading saves 25% (0.8s). Doc says “does not load applications (including from deps) before compiling”. Is there a short explanation as to what that entails / when not to use this?
Finally, is there a standard way to have mix feel less slugish?
Note: Not important whatsoever but time mix compilexxx takes an extra 15% (0.5s) to tell me that “The task “compilexxx” could not be found. Did you mean “compile”?” Seems like a lot of CPU cycles for that “did you mean …”!
One of the biggest changes in Elixir v1.11 was the tracking of application calls. We will now warn if you call an application you don’t depend on. This means that the loading of applications, which was done after compilation, is now done before compilation. This is the process of parsing .app files and loading them into memory. This probably explains a chunk of your time, since disabling app loading saves 0.8s. If you disable it, they are loaded and started at once later on.
Some extra suggestions:
Can you please measure the times for mix run -e ""? You are not supposed to see a large difference on those. Btw, what is the Elixir version you are measuring against?
You can use MIX_DEBUG=1 to track the time spent on each task
Phoenix master (upcoming v1.6) no longer requires the :phoenix compiler and that should save some additional time
mix compilexxx takes a lot of time because we need to go through all applications, load all existing mix tasks, and see if any of them may match. This is probably another action we can parallelize.
That doesn’t mean we can’t optimize things though. Application loading, for instance, is not parallel today, and we should be able to do so somewhat trivially.
As an appreciation for your work, I would be willing to jump into this codebase, if you could share it with me, or jump into a call and explore some ideas with you. Or perhaps sharing the mix.exs + mix.lock can be enough to reproduce a lot of it (you can erase lib and run again to check). Just let me know.
Thanks, that seem to explain the slowdown with elixir 1.12. All timings are with 1.12, except the initial point 1). So since mix test needs to start the applications anyways, there probably wouldn’t be such a slowdown.
time mix run -e "" => 3.9s (much slower than 2.9s)
$ MIX_DEBUG=1 time mix compile
-> Running mix loadconfig (inside Bobby.MixProject)
<- Ran mix loadconfig in 11ms
-> Running mix compile (inside Bobby.MixProject)
-> Running mix loadpaths (inside Bobby.MixProject)
-> Running mix archive.check (inside Bobby.MixProject)
<- Ran mix archive.check in 0ms
-> Running mix deps.loadpaths (inside Bobby.MixProject)
<- Ran mix deps.loadpaths in 396ms
<- Ran mix loadpaths in 398ms
-> Running mix compile.all (inside Bobby.MixProject)
-> Running mix compile.phoenix (inside Bobby.MixProject)
<- Ran mix compile.phoenix in 507ms
-> Running mix compile.gettext (inside Bobby.MixProject)
<- Ran mix compile.gettext in 5ms
-> Running mix compile.yecc (inside Bobby.MixProject)
<- Ran mix compile.yecc in 5ms
-> Running mix compile.leex (inside Bobby.MixProject)
<- Ran mix compile.leex in 0ms
-> Running mix compile.erlang (inside Bobby.MixProject)
<- Ran mix compile.erlang in 0ms
-> Running mix compile.elixir (inside Bobby.MixProject)
<- Ran mix compile.elixir in 52ms
-> Running mix compile.app (inside Bobby.MixProject)
<- Ran mix compile.app in 9ms
<- Ran mix compile.all in 1421ms
<- Ran mix compile in 1843ms
2.85 real 2.66 user 1.44 sys
Cool, would save 0.5s apparently
Makes sense. I wouldn’t spend a single second optimizing this
rm -rf lib/ => decreases from 2.9s to 2.2s. Also reduces the number of bugs to 0
Thank you so much for your generous offer. I asked my boss and I will contact you privately.
Sorry. I meant that you shouldn’t see a difference between mix run -e "" across Elixir versions. But I expect mix run -e "" to indeed have some additional time as it has to start all apps (and you have ~100 of them!)
I spent 15 minutes optimizing app loading and it now loads apps concurrently! If you are willing to give it a try, you can find it in the v1.12 branch too. Since you have 6 cores, I am hoping it will at least go down to 0.2s.
So hopefully this and the upcoming phoenix change shaves ~1.1s from your times. I will keep investigating!
EDIT 1: The 15 minutes actually became 1h because it turns out the code was reaching to a central process. I was able to optimize it by adding a fast paths to apps that come from deps (which are the huge majority). In a sample project I created with 50 deps, times went from 180ms to 50ms!
EDIT 2: I got an app with 150 deps and app loading time went from 920ms to 120ms!
Just one note on this. Some of the work in the :phoenix compiler is still necessary but it should be a bit faster. In particular, the work that is done by the :phoenix compiler is to look into view templates directories to find if new templates have been added. It is done by this function:
Maybe there is a faster way to compute this.
Btw, I think I no longer need access to the repo, as my home-made 150 deps monster lock file reproduced the slow downs locally. Thanks for checking though!
If you are willing to give it a try, you can find it in the v1.12 branch too. Since you have 6 cores, I am hoping it will at least go down to 0.2s.
