nduitz
November 16, 2020, 6:58pm
1
Hey there,
we are currently trying to migrate to Elixir 1.11.
We had a few warnings that needed to be fixed in our otp app. But now the compile step won’t finish and I have know idea where to start debugging.
Using the --verbose
flag I can confirm that all modules finish compilitation ( same output with 1.10 ).
But what is missing is the Generated hello app
output and the compiler does not continue with the web app.
We are using the elixir-1.11.2-slim docker image, but trying to compile without the docker environment shows the same behaviour.
I aborted the compiler to produce a crash dump. As this I am not good in reading this logs some things I think are unusual but might be totally normal:
All processes are in state waiting except for :erlang.apply/2
:erlang.apply/2 has a huge amount of reductions ~500_000_000
message queue is empty except for :erlang.apply/2 (one message)
I waited ~30m and nothing happens, but 1 cpu core is always at 100% usage.
Thanks for your help. A good start might be pointing me into a direction where to look for strange behaviours.
Cheers,
~Nick
axelson
November 16, 2020, 7:10pm
2
That sounds like it might be https://bugs.erlang.org/browse/ERL-1236
Are you using an affected version of Erlang?
nduitz
November 16, 2020, 7:24pm
3
Thanks for the reply.
As stated we are using the elixir-1.11.2-slim container which is based on the latest OTP 23 version: 23.1.2.
Since the issue says “soon releasing a fix for 23” posted in May, I guess this has been fixed.
Can you please try this:
MIX_DEBUG=1 mix compile --force --profile time
And post the results?
2 Likes
nduitz
November 16, 2020, 7:50pm
5
Sure thing (had to anonymize app name and module names):
my_app@3ce7524f5cdd:/app$ MIX_DEBUG=1 mix compile --force --profile time
** Running mix loadconfig (inside MyApp.Umbrella.Mixfile)
** Running mix compile --warnings-as-errors --force --profile time (inside MyApp.Umbrella.Mixfile)
** Running mix loadpaths --warnings-as-errors --force --profile time (inside MyApp.Umbrella.Mixfile)
** Running mix archive.check --warnings-as-errors --force --profile time (inside MyApp.Umbrella.Mixfile)
** Running mix deps.loadpaths --warnings-as-errors --force --profile time (inside MyApp.Umbrella.Mixfile)
** Running mix deps.precompile (inside MyApp.Umbrella.Mixfile)
==> geo_db
** Running mix compile --no-deps-loading --no-apps-loading --no-archives-check --no-elixir-version-check --no-warnings-as-errors (inside GeoDb.Mixfile)
** Running mix loadpaths --no-deps-loading --no-apps-loading --no-archives-check --no-elixir-version-check --no-warnings-as-errors (inside GeoDb.Mixfile)
** Running mix compile.all --no-deps-loading --no-apps-loading --no-archives-check --no-elixir-version-check --no-warnings-as-errors (inside GeoDb.Mixfile)
** Running mix compile.yecc --no-deps-loading --no-apps-loading --no-archives-check --no-elixir-version-check --no-warnings-as-errors (inside GeoDb.Mixfile)
** Running mix compile.leex --no-deps-loading --no-apps-loading --no-archives-check --no-elixir-version-check --no-warnings-as-errors (inside GeoDb.Mixfile)
** Running mix compile.erlang --no-deps-loading --no-apps-loading --no-archives-check --no-elixir-version-check --no-warnings-as-errors (inside GeoDb.Mixfile)
** Running mix compile.elixir --no-deps-loading --no-apps-loading --no-archives-check --no-elixir-version-check --no-warnings-as-errors (inside GeoDb.Mixfile)
** Running mix compile.app --no-deps-loading --no-apps-loading --no-archives-check --no-elixir-version-check --no-warnings-as-errors (inside GeoDb.Mixfile)
==> serving_domain_plug
** Running mix compile.all --warnings-as-errors --force --profile time (inside ServingDomainPlug.MixProject)
** Running mix compile.yecc --warnings-as-errors --force --profile time (inside ServingDomainPlug.MixProject)
** Running mix compile.leex --warnings-as-errors --force --profile time (inside ServingDomainPlug.MixProject)
** Running mix compile.erlang --warnings-as-errors --force --profile time (inside ServingDomainPlug.MixProject)
** Running mix compile.elixir --warnings-as-errors --force --profile time (inside ServingDomainPlug.MixProject)
Compiling 1 file (.ex)
[profile] lib/serving_domain_plug.ex compiled in 26ms
[profile] Finished compilation cycle of 1 modules in 26ms
[profile] Finished group pass check of 1 modules in 1ms
** Running mix compile.app --warnings-as-errors --force --profile time (inside ServingDomainPlug.MixProject)
Generated serving_domain_plug app
==> urmel
** Running mix compile.all --warnings-as-errors --force --profile time (inside Urmel.MixProject)
** Running mix compile.yecc --warnings-as-errors --force --profile time (inside Urmel.MixProject)
** Running mix compile.leex --warnings-as-errors --force --profile time (inside Urmel.MixProject)
** Running mix compile.erlang --warnings-as-errors --force --profile time (inside Urmel.MixProject)
** Running mix compile.elixir --warnings-as-errors --force --profile time (inside Urmel.MixProject)
Compiling 1 file (.ex)
[profile] lib/urmel.ex compiled in 118ms
[profile] Finished compilation cycle of 2 modules in 118ms
[profile] Finished group pass check of 2 modules in 5ms
** Running mix compile.app --warnings-as-errors --force --profile time (inside Urmel.MixProject)
Generated urmel app
==> my_app
** Running mix compile.all --warnings-as-errors --force --profile time (inside MyApp.Mixfile)
** Running mix compile.yecc --warnings-as-errors --force --profile time (inside MyApp.Mixfile)
** Running mix compile.leex --warnings-as-errors --force --profile time (inside MyApp.Mixfile)
** Running mix compile.erlang --warnings-as-errors --force --profile time (inside MyApp.Mixfile)
** Running mix compile.elixir --warnings-as-errors --force --profile time (inside MyApp.Mixfile)
Compiling 95 files (.ex)
[profile] lib/my_app/some/module.ex compiled in 114ms
[profile] lib/my_app/some.ex compiled in 129ms
[profile] lib/my_app/some.ex compiled in 176ms
[profile] lib/my_app/some/module.ex compiled in 284ms
[profile] lib/my_app/some/module.ex compiled in 254ms (plus 50ms waiting)
[profile] lib/my_app/some/module/submodule.ex compiled in 339ms
[profile] lib/my_app/some/module/submodule.ex compiled in 389ms
[profile] lib/my_app/some.ex compiled in 467ms
[profile] lib/my_app/some/module.ex compiled in 525ms
[profile] lib/my_app/some.ex compiled in 281ms
[profile] lib/my_app/some/module.ex compiled in 507ms
[profile] lib/my_app/some.ex compiled in 229ms
[profile] lib/my_app/some/module.ex compiled in 160ms
[profile] lib/my_app/some/module.ex compiled in 413ms
[profile] lib/my_app/some/module.ex compiled in 748ms
[profile] lib/my_app/some/module.ex compiled in 139ms
[profile] lib/my_app/some/module.ex compiled in 257ms
[profile] lib/my_app/some/module/submodule.ex compiled in 164ms
[profile] lib/my_app/some/module.ex compiled in 247ms
[profile] lib/my_app/some.ex compiled in 168ms
[profile] lib/my_app/some/module/submodule.ex compiled in 182ms
[profile] lib/my_app/some/module.ex compiled in 179ms
[profile] lib/my_app/some/module.ex compiled in 926ms
[profile] lib/my_app/some.ex compiled in 384ms
[profile] lib/my_app/some.ex compiled in 157ms
[profile] lib/my_app/some/module.ex compiled in 253ms
[profile] lib/my_app/some/module.ex compiled in 423ms
[profile] lib/my_app/some/module.ex compiled in 171ms
[profile] lib/my_app/some/module.ex compiled in 486ms
[profile] lib/my_app/some/module.ex compiled in 1067ms
[profile] lib/my_app/some.ex compiled in 631ms
[profile] lib/my_app/some/module.ex compiled in 163ms
[profile] lib/my_app/some/module.ex compiled in 1233ms
[profile] lib/my_app/some.ex compiled in 138ms
[profile] lib/my_app/some/module.ex compiled in 763ms
[profile] lib/my_app.some compiled in 93ms
[profile] lib/my_app/some.ex compiled in 631ms
[profile] lib/my_app/some.ex compiled in 311ms
[profile] lib/my_app/some/module.ex compiled in 364ms
[profile] lib/my_app/some/module/submodule.ex compiled in 297ms
[profile] lib/my_app/some/module/submodule.ex compiled in 438ms
[profile] lib/my_app/some/module.ex compiled in 905ms
[profile] lib/my_app/some/module.ex compiled in 449ms
[profile] lib/my_app/some.ex compiled in 787ms
[profile] lib/my_app/some.ex compiled in 303ms
[profile] lib/my_app/some/module.ex compiled in 245ms (plus 358ms waiting)
[profile] lib/my_app/some/module/submodule.ex compiled in 135ms
[profile] lib/my_app/some/module/submodule.ex compiled in 177ms
[profile] lib/my_app/some/module.ex compiled in 308ms
[profile] lib/my_app/some/module.ex compiled in 345ms
[profile] lib/my_app/some/module.ex compiled in 294ms
[profile] lib/my_app/some/module/submodule.ex compiled in 343ms
[profile] lib/my_app/some/module.ex compiled in 318ms
[profile] lib/my_app/some/module.ex compiled in 335ms (plus 2005ms waiting)
[profile] lib/my_app/some.ex compiled in 213ms
[profile] lib/my_app/some.ex compiled in 115ms
[profile] lib/my_app/some.ex compiled in 192ms
[profile] lib/my_app/some/module.ex compiled in 258ms
[profile] lib/my_app/some.ex compiled in 701ms
[profile] lib/my_app/some/module.ex compiled in 177ms
[profile] lib/my_app/some/module/submodule/poller.ex compiled in 198ms
[profile] lib/my_app/some.ex compiled in 238ms
[profile] lib/my_app/some/module.ex compiled in 302ms
[profile] lib/my_app/some.ex compiled in 561ms
[profile] lib/my_app/some.ex compiled in 858ms
[profile] lib/my_app/some/module/submodule.ex compiled in 1616ms
[profile] lib/my_app/some.ex compiled in 324ms
[profile] lib/my_app/some/module.ex compiled in 501ms
[profile] lib/my_app/some/module.ex compiled in 643ms
[profile] lib/my_app/some/module.ex compiled in 1096ms (plus 856ms waiting)
[profile] lib/my_app/some/module.ex compiled in 590ms
[profile] lib/my_app/some.ex compiled in 272ms
[profile] lib/my_app/some/module.ex compiled in 1982ms (plus 1548ms waiting)
[profile] lib/my_app/some/module/submodule.ex compiled in 165ms
[profile] lib/my_app/some/module.ex compiled in 844ms
[profile] lib/my_app/some/module.ex compiled in 168ms
[profile] lib/my_app/some/module/submodule.ex compiled in 574ms
[profile] lib/my_app/some/module/submodule.ex compiled in 861ms
[profile] lib/my_app/some.ex compiled in 367ms
[profile] lib/my_app/some/module.ex compiled in 890ms (plus 2232ms waiting)
[profile] lib/my_app/some/module.ex compiled in 606ms (plus 96ms waiting)
[profile] lib/my_app/some/module.ex compiled in 440ms (plus 29ms waiting)
[profile] lib/my_app/some/module.ex compiled in 728ms (plus 3182ms waiting)
[profile] lib/my_app/some/module.ex compiled in 488ms (plus 2336ms waiting)
[profile] lib/my_app/some/module.ex compiled in 483ms (plus 2601ms waiting)
[profile] lib/my_app/some/module.ex compiled in 572ms (plus 3061ms waiting)
[profile] lib/my_app/some/module.ex compiled in 858ms (plus 1838ms waiting)
[profile] lib/my_app/some/module.ex compiled in 1424ms (plus 470ms waiting)
[profile] lib/my_app/some/module.ex compiled in 1114ms (plus 153ms waiting)
[profile] lib/my_app/some/module.ex compiled in 207ms (plus 2950ms waiting)
[profile] lib/my_app/some/module/submodule.ex compiled in 533ms (plus 1982ms waiting)
[profile] lib/my_app/some/module.ex compiled in 656ms (plus 2316ms waiting)
[profile] lib/my_app/some/module.ex compiled in 1526ms
[profile] lib/my_app/some/module.ex compiled in 2646ms
[profile] lib/my_app/some/module.ex compiled in 1212ms (plus 3918ms waiting)
[profile] Finished compilation cycle of 178 modules in 5133ms
this is where it stops doing anything visible (except for high cpu usage)
compilation of my_app_web
and my_app_api
is missing.
Ok. Next Elixir is supposed to run a group pass and it seems we are getting stuck on it. This means there is one module in all of those that is slowing things down. My suggestion is to remove modules one by one and compile, until you find the slow one. If you send me the project in private (see my contact info on GitHub) I can debug it too.
2 Likes
nduitz
November 17, 2020, 9:08am
7
Thanks for the offer! I’ll try myself first and then beg for help if I am stuck again
Is there a possibility that a dependency might disturb the compiling process?
nduitz
November 17, 2020, 10:12am
8
Hey there,
thanks again, you were right. I narrowed it down to a single, more likely two lines of code.
I fixed it but I don’t quite understand the issue:
# contains some more fields that are not important for the demonstration
%{consumption: %Consumption{}} = queried = some_query_function()
with(
true <- is_nil(queried.consumption.video_started_at)
update_arguments <- %{
consumption: queried.consumption
}
) do
removing one of those two accesses (either queried.consumption
or queried.consumption.video_started_at
) resolves the compiling issue. It doesn’t matter which one.
So I replaced the first check with:
%{consumption: %{video_started_at: nil}} <- queried
and it works.
Do you have any idea why?
Might there be an issue with the new compiler checks here?
Awesome job! Can you please give me a minimal function that reproduces the issue? Run mix new example
and try to copy only the minimal amount of code (most likely a single module with a single single function) that reproduces it and we will readily take a look at it and push a fix to master.
2 Likes
nduitz
November 17, 2020, 12:11pm
10
There you go:
I noticed that it’s not just the two lines but a synergy with a macro we are using, so I provided that too.
2 Likes
Thanks, here is a further minimal case:
defmodule CompilerExample do
def hello(queried) do
with(
true <- is_nil(queried.foo.bar),
_ = queried.foo
) do
%{foo: %{other_id: _other_id} = foo} = queried
%{other_id: id} = foo
%{id: id}
end
end
end
We are looking into the root cause now.
nduitz
November 18, 2020, 11:55am
13
Thank you for your help and quick fixing <3
But even with you fix I don’t quite understand the problem.
Could you shortly explain the problem? That would be nice
Cheers
~Nick
1 Like