Understanding a spike in app compilation time

Questions / Help
,
1

I’m investigating a spike in app compilation times, and would appreciate ideas / validation of the paths I am exploring.

I have a huge app at hand, consisting of hundreds of .ex files. Recently, our team noticed that changes to even seemingly innocent / un-related files cause a massive recompilation of more than 120 files in the project.

Using git-bisect & a small homegrown script that “measures” recompilation, I’ve boiled down an issue to a particular commit from a couple of months back. The script, in a nutshell, does this (original script omitted for brevity):

mix compile # takes time
mix compile # instant
echo "# just a comment" >> lib/my_module.ex
mix compile # takes time

With the problematic commit checked out, the last line of the script above causes more than 120 files to re-compile. With an immediate parent commit checked out, the script causes recompilations of only slightly over 30 files.

Carefully inspecting the diff of the offending commit, and playing with modifications to its patch, I’ve boiled it down to a particular line that refers to lib/my_other_module.ex module. If the line (e.g. a reference to the module) is removed, recompilations are back to normal ~30. But there’s problem:

  • the modified patch in question has no apparent relation to lib/my_module.ex,
  • the modified line with reference to lib/my_other_module.ex also has no apparent visible relation to lib/my_module.ex.

I am now trying to find an answer to a question: what is it in the relationship between lib/my_module.ex and lib/my_other_module.ex that causes recompilation? With this question in mind, I started running experiments using mix xref .

One particular test revealed a dramatic increase in compile-time dependencies for lib/my_module.ex:

$ git checkout 495b41fa
$ mix xref graph --label compile --sink lib/my_module.ex --only-nodes | wc -l
0

$ git checkout 1204cb24
$ mix xref graph --label compile --sink lib/my_module.ex --only-nodes | wc -l
122

This change in number is… intriguing. But frankly, I am not sure where to go from here :thinking:

I’ll continue my investigation, but in the meantime: is there any other data I should look at when running mix xref graph that could bring me closer to understanding what’s going on?

1 Like
2

Did you look at the graph xref prints? It should give you a path of how those files are connected.

3

You probably have some transitive compile time dependencies, where module A needs module B to compile, but to compile module B you need to compile C.

The command mix xref graph --label compile --sink lib/my_module.ex is a good starting point, the files listed depend on lib/my_module.ex to compile, so any change to it will recompile all of them.

These are some pages to understand what is going on and how to fix compile time dependencies:

4 Likes
4

Thanks, yes, I did. After looking at mix xref graph I’m left even more puzzled now.

There is a path from lib/my_module.ex to lib/my_other_module.ex. But, in comparing it in two commits, good and bad, there’s a noticeable change in a tree. This is puzzling, because offending commit did not change anything between lib/my_module.ex to lib/my_other_module.ex: it merely introduced a dependency on lib/my_other_module.ex in an un-related place.

I’m going to read through @marcandre gist now - have not seen this one. Thanks for pointers, @ypconstante!

5

Transitive compile time dependencies can be tricky, because a plain runtime dependency can introduce additional compile time dependencies elsewhere.

1 Like
6

Do you have any modules referencing each other? I found this was the biggest offender in a codebase I came into that had a very high recompilation count. Some were hard to trace because they would be somewhat cyclical where A would reference B which would reference C which would reference D which would reference back to A. You can see these in the xref output when the same file shows up multiple times in the same branching path (and can cause these branching “explosions”). It could be what’s happening in this scenario if lib/my_other_module.ex has some other connection in the opposite direction to lib/my_module.ex.

2 Likes
7

Following the guide, deps.md · GitHub, I am slowly going through our codebase and fixing excess compile-time dependencies. I hope my progress continues that way.

One thing that I am failing to explain to myself if the following - how come running first command does not reveal compile-time dependencies to files containing PublicApi.OpenApi.DocumentPdf.Show.Response and PublicApi.OpenApi.DocumentPdf.ShowAccepted.Response?

$ mix xref graph --label compile-connected --source lib/public_api/controllers/document_pdf_controller.ex
lib/public_api/controllers/document_pdf_controller.ex
├── lib/public_api/open_api/render_error.ex (compile)
├── lib/public_api/open_api/schemas/errors.ex (compile)
└── lib/public_api/open_api/spec.ex (compile)

$  mix xref trace lib/public_api/controllers/document_pdf_controller.ex --label compile
lib/public_api/controllers/document_pdf_controller.ex:2: call PublicApi.Web.__using__/1 (compile)
lib/public_api/controllers/document_pdf_controller.ex:37: alias PublicApi.OpenApi.DocumentPdf.Show.Response (compile)
lib/public_api/controllers/document_pdf_controller.ex:38: alias PublicApi.OpenApi.DocumentPdf.ShowAccepted.Response (compile)
lib/public_api/controllers/document_pdf_controller.ex:39: alias PublicApi.OpenApi.Schemas.Error.Unauthorized (compile)
lib/public_api/controllers/document_pdf_controller.ex:40: alias PublicApi.OpenApi.Schemas.Error.Forbidden (compile)
lib/public_api/controllers/document_pdf_controller.ex:41: alias PublicApi.OpenApi.Schemas.Error.NotFound (compile)
lib/public_api/controllers/document_pdf_controller.ex:42: alias PublicApi.OpenApi.Schemas.Error.UnprocessableEntity (compile)
lib/public_api/controllers/document_pdf_controller.ex:43: alias PublicApi.OpenApi.Schemas.Error.ServiceUnavailable (compile)
nofile:10: alias PublicApi.OpenApi.Spec (compile)
nofile:12: alias PublicApi.OpenApi.RenderError (compile)

cc @mbuhot would you have an idea, by any chance? :thinking:

8

Do you have any modules referencing each other?

Do you mean cycles?

Yes, throughout the years we’ve accumulated plenty of those, unfortunately. I am currently going through the codebase and reaping some low-hanging fruits first, before getting to untangling the cycles.

9

Ya I mean cycles and yes, I was actually never able to untangle those as it would have taken forever and I didn’t last long enough at the company (some where 6 or 7 deep).

10

Another (small) mystery. Leaving a note about it here, so I could come back later to investigate in isolation.

@doc module attribute supports being given value of a keyword list. If module name is used somewhere in the keyword list, it will be registered as a compile-time dependency for a module at hand.

In the following example delegate does not cause a compile-time dependency, but @doc does:

defmodule MyModule do
  @doc delegate_to: {MyOtherModule, :my_function, 2}
  defdelegate my_function(x, y), to: MyOtherModule
end

Results in this:

$ mix xref graph --label compile-connected
lib/my_module.ex
└ lib/my_other_module.ex (compile)
$

It’s fixable by converting MyOtherModule into :"MyOtherModule" (which is kind of ugly)

11

There was some suggestions from @josevalim a while back on reducing the compile time dependencies between schema modules in Move schema definition to inside functions · Issue #382 · open-api-spex/open_api_spex · GitHub

One short term fix would be to replace module names with explicit %Reference{} structs.

OpenApiSpex.schema(%{
  title: "UserRequest",
  type: :object,
  properties: %{
    user: User
  }
}

would become

OpenApiSpex.schema(%{
  title: "UserRequest",
  type: :object,
  properties: %{
    user: %Reference{"$ref": "#/components/schemas/User"}
  }
}
2 Likes
12

Thanks, @mbuhot! Following your advice, I was able to remove all transitive dependencies related to specs.

Working on it made me realise something else too. When cleaning up controllers, hence working on “operations”, I’ve converted all:

operation(:create,
  # ...
)

to:

def create_operation do
  %Operation{
    # ...
  }
end

This way all previously compile-time dependencies caused by various mentions of schemas inside the operation - became runtime dependencies.

Changes this turned out a bit of work though.

1 Like
13

I wrote a few blog posts on this topic that might help, part 3 probably most useful:

3 Likes
14

That’s a great series Tim! Two quick notes I noticed on the most recent read. “ By simply using alias instead no compile-time dependencies are created.” should say export instead of compile-time. Also consider mentioning mix xref trace FILE if you haven’t yet which really helps show what is compile/runtime/export in a given file. Thanks!

15

Thanks, updated!