Can you try with the āprofile time option to mix compile? I am suspecting a type system related slowdown (you can also try v1.19 branch, we just pushed more optimizations).
Thanks @josevalim . Iām not sure what to look for when using āprofile timeā¦ Thereās a lot of output . What can I do to help figure out the source of the slowdown? Do I need the output from 1.18 and what would I compare?
Wait a second. Compilation took 21s but the Mix task took 33s?! Try running āmix compile āforceā with MIX_DEBUG=1 and see which task is taking long.
Right. Thereās a sizeable delay that doesnāt have any output, even with MIX_DEBUG=1:
MIX_DEBUG=1 time mix compile --force --profile time
-> Running mix CLI
-> Running mix loadconfig (inside Enaia.MixProject)
<- Ran mix loadconfig in 4ms
-> Running mix compile --force --profile time (inside Enaia.MixProject)
-> Running mix loadpaths --force --profile time (inside Enaia.MixProject)
-> Running mix deps.loadpaths --force --profile time (inside Enaia.MixProject)
-> Running mix archive.check --force --profile time (inside Enaia.MixProject)
<- Ran mix archive.check in 0ms
<- Ran mix deps.loadpaths in 366ms
<- Ran mix loadpaths in 367ms
-> Running mix compile.all --force --profile time (inside Enaia.MixProject)
-> Running mix compile.phoenix_live_view --force --profile time (inside Enaia.MixProject)
<- Ran mix compile.phoenix_live_view in 0ms
-> Running mix compile.erlang --force --profile time (inside Enaia.MixProject)
<- Ran mix compile.erlang in 0ms
-> Running mix compile.elixir --force --profile time (inside Enaia.MixProject)
Compiling 1397 files (.ex)
[profile] ...
[profile] Finished cycle resolution in 1ms
[profile] Finished compilation cycle of 1648 modules in 19888ms
[profile] Finished group pass check of 1648 modules in 1395ms
<- Ran mix compile.elixir in 30639ms
-> Running mix compile.app --force --profile time (inside Enaia.MixProject)
Generated enaia app
<- Ran mix compile.app in 26ms
-> Running mix compile.surface --force --profile time (inside Enaia.MixProject)
<- Ran mix compile.surface in 1604ms
-> Running mix compile.yecc --force --profile time (inside Enaia.MixProject)
<- Ran mix compile.yecc in 0ms
-> Running mix compile.leex --force --profile time (inside Enaia.MixProject)
<- Ran mix compile.leex in 0ms
<- Ran mix compile.all in 32300ms
<- Ran mix compile in 32792ms
<- Ran mix CLI in 32848ms
33.08 real 171.14 user 20.15 sys
Ok, good news is that it is not compiler related, bad news is that we donāt have instrumentation around the areas that are slow now.
When does the delay happen? Before it starts compiling each module? In the middle? At the end? My suggestion is to add some print statements around mix/compilers/elixir.ex and try to get a feeling where in the code the slowdown is.
Paying more attention to it, the mysterious delay is after the ācompilation cycleā and before the āgroup pass checkā:
[profile] Finished compilation cycle of 1648 modules in 19888ms
# At least 10 seconds passes
[profile] Finished group pass check of 1648 modules in 1395ms
<- Ran mix compile.elixir in 30639ms
No. I have a hunch this is protocol consolidation. If you open up mix/compilers/elixir.ex, you will see each_cycle and after_compile callbacks, measure those!
I recommend GitHub - zmwangx/ets: Command output timestamper as a tool to show you how much each step of a command took (with the caveat that each step must output a new line in the terminal).
The incremental mode does not always work so I just use the elapsed mode i.e.
ets -s -c -f '[%T.%f]' ping google.com
Iāve used this many times to help me identify slow spots.
I pushed a commit that measures what is happening within those 10 seconds, so you can try the v1.19 branch. In a nutshell, we do two things:
we write files to disk
we consolidate protocols
Then let me know the times reported.
I donāt think it is the āwriting to diskā bit, cause that was happening before anyway, but I was able to optimize it anyway (a project with 1000 modules went from 1s to 333ms on my machine). I donāt think the gain will be noticeable in practice though, unless you are using containers or network drives.
On the other hand, we did change considerably how protocol consolidation works on v1.19, so perhaps a regression there?
I created a project with 10 protocols with 200 implementations each, and the consolidation pass is 3 seconds:
protos =
for i <- 1..10 do
defprotocol Module.concat(Proto, "M#{i}") do
def foo_bar(x)
end
Module.concat(Proto, "M#{i}")
end
for j <- 1..200 do
defmodule Module.concat(Foo, "M#{j}") do
defstruct [:foo]
for proto <- protos do
defimpl proto do
def foo_bar(x), do: x
end
end
end
end
So in case both the writing and consolidation are fast in your case, you may need to add some debugging statements to find the root cause.
PS: I also saw that you changed Erlang/OTP versions. Try running v1.19 with the same OTP version to rule out an issue with OTP!
Details:
I re-ran it in 1.18 just to confirm that the protocol consolidation / file writing was faster in 1.18:
[profile] Finished compilation cycle of 1648 modules in 20759ms
# About 3 seconds in 1.18, which matches the overall time
[profile] Finished group pass check of 1648 modules in 1069ms
<- Ran mix compile.elixir in 23795ms
I can also confirm that OTP has no impact (i.e. 1.19 with older OTP version is also slow)
Compiling with the latest changes gives the following output:
[profile] Finished cycle resolution in 0ms
[profile] Finished compilation cycle of 1648 modules in 21185ms
[profile] Finished writing modules to disk in 284ms
[profile] Finished after compile callback in 8216ms
[profile] Finished group pass check of 1648 modules in 6402ms
<- Ran mix compile.elixir in 36360ms
So āafter compile callbackā is indeed slow, but strangely āgroup pass checkā is also slower in 1.20.
So I started from 1.19.1ās source and just added the āafter compile callbackā output and got back the quicker āgroup pass checkā:
[profile] Finished cycle resolution in 0ms
[profile] Finished compilation cycle of 1648 modules in 21974ms
[profile] Finished after compile callback in 9124ms
[profile] Finished group pass check of 1648 modules in 1398ms
<- Ran mix compile.elixir in 34360ms
So āafter compile callbackā is indeed slow, but strangely āgroup pass checkā is also slower in 1.20.
It is slower because we are already doing even more inference on v1.20. We will probably need to improve the performance though before we ship it, but we can postpone this conversation a bit.
Back to the issue at hand, I recommend measuring some times here:
And I assume maybe_consolidate is the slow one:
So you may need to break Mix.Compilers.Protocol down. Unfortunately I could not reproduce it by brute forcing (compiling hundreds of protocols), so there may be something project specific.
This is very weird indeed, because extract_protocols did not change at all! I can only think that somehow :beam_lib.chunks is way more expensive now? Do you see a large difference in .beam file sizes?
PS: I pushed a new commit to the v1.19 branch if you want to validate this theory.
Thanks and thanks for confirming extract_protocols has not changed.
I wanted to double check whatās going on in 1.18.4 but I get a compilation error in a dependency when I compile from source, very strange.
I probably wonāt have time to check further until next Tuesday.
.
!
