Slow Phoenix.CodeReloader

Questions & Help Questions
,
1

Hello there,

I was troubleshooting a fast request (the plug is fast, under 10ms), that was taking between 100ms and 120ms if these lines are in the endpoint config

  if code_reloading? do
    # takes around 100ms
    plug Phoenix.CodeReloader
  end

Looking at the code it’s a pretty standard call to Code.ensure_loaded? which I saw somewhere could be slow (which seems normal since it probably has to check all the files).

LiveReloader takes adventage of inotify (and equivalents in other ecosystems) to only trigger work if there was an actual change to an interesting file. Maybe we could subscribe to such events and check this before calling ensure_loaded??

We have around 1600+ files in the lib/ folder. I’m considering turning off the plug now that I know that my local development could be more responsive (100ms is a lot, especially if there are many requests on a page), but I’d definitely miss code reloading…

2

How many files are recompiled when you make a change? Cause the ensure_loaded? waits until the module becomes available again which might take a while if there a lots of (trans) compilation dependencies.

There are a few techniques to reduce the compile time dependencies which might speed things up.

3

The 100ms delay is always there, even when there are no file changes. Sorry it wasn’t clear enough!

When there is work to be done, I don’t mind waiting a few seconds to have my page ready. (we’re unfortunately hitting this kind of timings…)

4

Is this true for a newly created project?

5

You are right large projects will take a bit longer. Since you said several requests per page, are you using a client framework? Is it API only? I wonder if we could skip code reloading depending on the type of request.

6

I think this would happen for a new project with the same number of files, and of course would linearly decrease to the case of a new project with just a few files where I guess it’s barely noticeable.

Our project isn’t API only but provides HEEx rendered pages that then make multiple new calls for datagrids, and for example opening an accordion in that grid would then lazy load the data for that item.

Each of those request would theoretically need to be invalidated if the code changed in between. Other requests such as static assets are defined in earlier in the plug pipeline so they’re not subject to that latency.

We are transitioning to LVs where possible, but for most of the legacy app, this is still a thing.

It’s true that we could maybe optimize on our end by checking only for “root” pages and leaving ajax requests alone, but it’s not rare to focus on a specific request during development (open it in a new tab and/or curl), so that would hinder that. It’s exactly on that use case that I noticed the issue, I was expecting the endpoint to return under 10ms, but it wasn’t, so I dug deeper. I see this as a potential source of questioning for others with similar sized projects.

Thanks for considering our issue!

7

Are you able to share your xref report so we have an idea if this is just due to the amount of files or because there are a lot of transitive dependencies.

I assume it’s the latter, and it can be a hard problem since the compiler has to wait and resolve the conflicts, and then you lose the benefits of parallel compilation.

8

Here’s a redacted output of xref graph --format stats, let me know if need more info.

Tracked files (nodes): 1637
Compile dependencies (edges): 2753
Exports dependencies (edges): 3827
Runtime dependencies (edges): 8529
Cycles: 572

Top 10 files with most outgoing dependencies:

  * lib/module/web/router.ex (195)
  * lib/module/domain/context_one.ex (70)
  * lib/module/domain/entity_one.ex (68)
  * lib/module/service/resolver_one.ex (64)
  * lib/module/web/controller/controller_one.ex (58)
  * lib/module/web/view/view_one.ex (55)
  * lib/module/data/exporter_one.ex (55)
  * lib/module/domain/context_two.ex (53)
  * lib/module/domain/context_three.ex (53)
  * lib/module/domain/context_four.ex (52)

Top 10 files with most incoming dependencies:

  * lib/module/core/localization.ex (711)
  * lib/module/core/localization/macros.ex (706)
  * lib/module/core/core.ex (706)
  * lib/module/web/router.ex (458)
  * lib/module/web/endpoint.ex (456)
  * lib/module/web/web.ex (454)
  * lib/module/utils/utils.ex (430)
  * lib/module/domain/entity_one.ex (406)
  * lib/module/data/repository.ex (359)
  * lib/module/web/component/component_library.ex (220)

Shouldn’t we not have to do any check if we can assert that no files were modified? IIRC my earlier compiler cache deep dives, the compiler checks for mtimes of files to detect dirtyness, so it should for our case return “nothing to do”, and my intuition is that this is what is taking time here, and not compiling per se.

Our compile times are not fast, but I think that’s an other topic :sad_but_relieved_face:

EDIT: a brand new project doesn’t show any delay

9

Great can you give this command a go: mix xref graph --label compile-connected

10

It’s 1251 lines long. What I can summarize from the output:

There are 458 tree heads
273 trees have 1 child
109 have 2 children
37 have 3 children
21 have 4 children

The rest 18 trees have between 5 and 9 children. We have made efforts to avoid transitive dependencies, but some are just required.

11

Yeah it can be hard, pattern matching on structs in function heads can be detrimental, although it is nice, I’m starting to just use a regular map instead.

Not sure if that is something that is causing your codebase issues, but it is easy way to avoid them.

12

Structs are export dependencies and should not lead to large recompilations by default.

We do explain how to reduce the number of compiled files in xref docs: mix xref — Mix v1.20.2

Elixir v1.19 also comes with some important improvements on compile time, especially for large projects (in the order of 1.5 to 2x faster).

13

Great, I might have been holding on to a myth from the past, I remember on a huge project where we ended up pattern matching structs in function headers across modules, causing huge number of modules to get recompiled constantly. But sounds great if that is a relic from the past.

14

I dug a little deeper and have a few findings to report:

First, we have one extra compiler to extract verified routes to a JSON “lock file” for consumption by an internal JS linter. It was not updated in a while it was reading the manifest (using Mix.Compilers.Elixir.read_manifest) in an attempt to not serialize the routes if not necessary.

It turned out the manifest read was actually the most expensive operation, taking around 20ms, the manifest is 481K.

For me that’s a lot to read a file into structs, but since the call basically reads as “read file” (which is fast) and “call :erlang.binary_to_term”, I don’t know if we have a lot of leeway here.

In the end, it turns out it’s faster to write the JSON for each call (calling Phoenix.Router.routes and writing the file takes 1ms) rather than trying to check if we actually have work to do…

I’d say compilers should be run in parallel, that could potentially help in the case of multiple compiles takings tens of ms in normal operation.

We’d also need a better way to tell if there is work to do than reading the manifest for custom compilers as apparently that’s expensive :sad_but_relieved_face: I don’t really like switching to an “always do the side effect” basis, as, it’s going to be called for each request…

The elixir compiler still times 50ms for a noop which I hope can be optimized too. Since the elixir compiler also reads the manifest I guess at least 20ms are spent there too but I didn’t dug there yet as it’s less convenient that just modifying a few .ex in the deps folder.

Then there’s an app compiler that takes 1ms.

Also, occasionally the compilers appear to run twice. I didn’t manage to find a pattern:

Compiler elixir time: 52 ms
Compiler app time: 3 ms
Compiler routes_js time: 1 ms
Compiler elixir time: 50 ms
Compiler app time: 3 ms
Compiler routes_js time: 1 ms

EDIT: the pipeline runs twice on app start, then twice on the first request, then once per request.
EDIT2: i think this is because of the LV connecting… maybe? let’s put this aside for now, not sure exactly of the pattern

15

Another dive later, I can report most of the time is spent:

  • reading the manifest into memory
  • getting the list of files to compile (Path.wildcard)
  • for each file, syscall of stat to get mtime and size (mtimes_and_sizes/1)
  • ~writing back the manifest~ (already skipped if :noop)

Not so much we can do here. There is no syscall to get file stats of that many files in bulk anyway.

Now I understand the bottleneck is IO, I realize I didn’t share my setup ; BRTFS on archlinux. It may be slower / faster on other OSs and/or file systems (curious to hear others on this).

I did debug this by calling mix compile (which is more or less what CodeReloader does). There, the intent is to compile and we can’t store state between invocations (well we does, the manifest. Thus storing state is costly for that use case).

My initial suggestion to rely on fs events, when compilation is called from a running process, could still be applied to CodeReloader to ensure we call mix.compile only when relevant. We could even proactively call compile on fs events to gain a few seconds between “editor saved” and “go back to the browser and refresh” if the user chooses so.