I recommend GitHub - zmwangx/ets: Command output timestamper · GitHub 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:
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!
Thanks @josevalim!
Findings:
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.
To my surprise, Protocol.extract_protocols takes about 4.4 seconds while consolidate takes 3.7 seconds, so both of these are significantly slower.
Consolidation per protocol (de-parallelized for easy timing) doesn’t reveal any particular outlier:
14 IEx.Info
15 Hex.Solver.Constraint
16 List.Chars
30 Collectable
34 Enumerable
51 String.Chars
68 JSON.Encoder
71 Enaia.CRE.Deal.Timeline.Event
77 Browser.Ua
77 Cldr.DisplayName
79 Enaia.Comments.Commentable
81 Cldr.Chars
81 Scrivener.Paginater
83 Phoenix.HTML.FormData
85 Ecto.Queryable
85 FunWithFlags.Group
88 Bamboo.Formatter
88 Table.Reader
89 LogfmtEx.ValueEncoder
93 Enaia.ActivityTracker.Trackable
94 Appsignal.Metadata
94 EnaiaWeb.Live.Helpers.ColumnItemGenerator
94 Phoenix.HTML.Safe
97 Enaia.CRE.Account.Address
97 Enaia.SpaceRenderable
98 Enaia.Documents.PDFConvertible
98 Timex.Protocol
100 DBConnection.Query
104 Poison.Decoder
109 Number.Conversion
110 Phoenix.Param
113 FunWithFlags.Actor
116 Bandit.WebSocket.Socket
116 Plug.Exception
116 Timex.Comparable
118 Cldr.LanguageTag.Chars
130 Bandit.HTTPTransport
131 ExTwilio.JWT.Grant
133 Oban.Met.Value
135 Ecto.DevLogger.PrintableParameter
157 Solid.Block
167 Inspect
204 Solid.Matcher
204 Solid.Renderable
207 ExAws.Operation
215 Bandit.WebSocket.Frame.Serializable
236 Enaia.Errors.Reportable
262 Poison.Encoder
279 Bandit.HTTP2.Frame.Serializable
597 Jason.Encoder
I don’t have time to dig much further today
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.
This has been fixed here and backported to v1.19: Optimize protocol consolidation · elixir-lang/elixir@995f7fc · GitHub
Since it changes how protocol consolidation works, I want to give it a try locally for a few days, and we can probably ship a new version on the new year.
