Elixir 1.19 compilation performance - have you noticed a difference?

The compiler is definitely doing more work overall in 1.19.X, so make sure you’re leveraging the MIX_OS_DEPS_COMPILE_PARTITION_COUNT env var, described here: elixir/CHANGELOG.md at v1.19 · elixir-lang/elixir · GitHub

If the compilation is still longer overall after setting that value to around half your cores, I’d open a bug, as I don’t think that’s expected.

Also, you’re the freedom_formatter guy! Thanks for the trailing commas !

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. Unfortunately specifying MIX_OS_DEPS_COMPILE_PARTITION_COUNT=2 didn’t noticeably change the results.

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

Is this when the type checking is happening?

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!