scottming

How to speed up the start of `mix test`?

I work on a very large umbrella project. I did this config in my web app:

config :logger,
  level: String.to_atom(System.get_env("LOGGER_LEVEL") || "info"),
  handle_otp_reports: true,
  handle_sasl_reports: true

config :my_web, MyWeb.Gettext, one_module_per_locale: true, allowed_locales: ["en"]

But finally, I found that when I was testing a file, it took almost 5 seconds before my gettext app started:

These are the top logs when I run mix test filename.exs at 11:10:30:

11:10:35.496 [info]  Child Gettext.ExtractorAgent of Supervisor #PID<0.4876.0> (Supervisor.Default) started
Pid: #PID<0.4877.0>
Start Call: Gettext.ExtractorAgent.start_link([])
Restart: :permanent
Shutdown: 5000
Type: :worker

then, I removed the gettext deps, but It doesn’t solve the problem.

These are the top logs when I run mix test filename.exs at 12:37:00 after I remove the gettext deps:

2021-10-31 12:37:04.800 [info] module=application_controller function=info_started/2 line=2089  Application logger started at :nonode@nohost
2021-10-31 12:37:04.844 [info] module=supervisor function=report_progress/2 line=1546  Child :ttb_autostart of Supervisor :runtime_tools_sup started
Pid: #PID<0.4893.0>

References

Speed up the compilation of Elixir projects that use Gettext | Angelika.me

23 comments

#compile #test

0 4825 23

2024-06-03 13:06:58 UTC

Marked As Solved

scottming

FYI, I have found a solution to this problem by working at the editor tool plugin level. Now my tests for complex projects that take more than 10 seconds take less than 1 second to run on iex, and those for simple projects usually take only 0.2 seconds. The experience from this speed is excellent.

I have written my own plugin: Elixir Test in IEx - Visual Studio Marketplace, which is very handy for Vscode users

Jhon Pedroza is working on the nvim neotest side of the integration: IEx strategy by jfpedroza · Pull Request #14 · jfpedroza/neotest-elixir · GitHub; and if you want to quickly experience vscode-like effects, you can also use these simple command define:

vim.api.nvim_create_user_command("TestIexStart", function()
	local code = 'Code.eval_file("~/.test_iex/lib/test_iex.ex");TestIex.start()'
	toggleterm.exec(string.format("MIX_ENV=test iex --no-pry -S mix run -e %q", code), 1)
	ttt.get_or_create_term(1):close()
end, {})

vim.api.nvim_create_user_command("TestFileAtCursorInIex", function()
	local line_col = vim.api.nvim_win_get_cursor(0)[1]
	local path = vim.fn.expand("%")
	local test_command = string.format("TestIex.test(%q, %q)", path, line_col)
	if vim.endswith(path, ".exs") then
		toggleterm.exec(test_command, 1)
		vim.g.last_test_in_iex_command = test_command
	else
		toggleterm.exec(vim.g.last_test_in_iex_command, 1)
	end
end, {})

vim.api.nvim_create_user_command("TestFileInIex", function()
	local path = vim.fn.expand("%")
	local test_command = string.format("TestIex.test(%q)", path)
	if vim.endswith(path, ".exs") then
		toggleterm.exec(test_command, 1)
		vim.g.last_test_in_iex_command = test_command
	else
		toggleterm.exec(vim.g.last_test_in_iex_command, 1)
	end
end, {})

Post #18

Also Liked

josevalim

Creator of Elixir

You can run MIX_DEBUG=1 mix test and it will show you the timing to run tasks in recent Elixir versions. If you are on Elixir v1.11 or later and you have a Phoenix application running on latest v1.5 or v1.6, you can remove the :phoenix compiler in the :compilers option of your mix.exs. That should speed it up by 2-3s in large apps.

Post #2

al2o3cr

I’ve seen this kind of “silent hang” in situations when multiple sandboxed tests tried to insert the same value for a column with a unique constraint.

None of the INSERTs can report success or failure until the other one’s transaction commits or aborts, so everything comes to a halt.

That usually produced one error per connection in the pool, though. In your case, matching the number of repos suggests something different might be happening.

Post #20

shamshirz

Updates!

Thanks so much for the ideas y’all! Interesting turn of events, I went digging into the DB side of this because we have addressed issues like transaction locks in the past and implemented unique values for constrained columns, but I think I misled us!

Red Herring - DB timeout

My current hypothesis is that the DBConnection.ConnectionError) owner #PID<0.726.0> timed out because it owned the connection for longer than 120000ms timeout is a redherring! It is timing out and worth looking into, but the DB isn’t the cause of the timeout, it’s just reporting that it’s been blocked for quite a while with an open connection(? I think).

I re-ran tests locally to discover that the cover portion of the test command is using most of the unaccounted-for time!

### Just Test (21s)
> time MIX_DEBUG=1 mix test test/crowbar/scan/vciso_card_test.exs > tmp.txt && elixir ./analyze.exs

### Partitioned (21s)
> time MIX_TEST_PARTITION=1 MIX_DEBUG=1 mix test test/crowbar/scan/vciso_card_test.exs --partitions 2 > tmp.txt && elixir ./analyze.exs

### Cover (61s)
> time MIX_DEBUG=1 mix test test/crowbar/scan/vciso_card_test.exs --cover > tmp.txt && elixir ./analyze.exs

### Partition & Cover (73s)
> time MIX_TEST_PARTITION=1 MIX_DEBUG=1 mix test test/crowbar/scan/vciso_card_test.exs --partitions 2 --cover > tmp.txt && elixir ./analyze.exs

I put the analyze.exs into a Gist here if you want to recreate. Should be code base agnostic.

New Hypothesis: ExCoveralls is using the time!

I annotated ExCoveralls locally to reproduce and I found the time here

-> Running mix test test/crowbar/scan/vciso_card_test.exs --cover (inside Crowbar.Mixfile)
-> Running ExCoveralls Cover.compile
<- Ran ExCoveralls Cover.compile in 25757ms
…
Finished in 4.9 seconds (4.9s async, 0.00s sync)
…
-> Running ExCoveralls Cover.execute
<- Ran ExCoveralls Cover.execute in 13249ms
<- Ran mix test in 43973ms

This example just ran 1 test file, but the time breakdown is clear
44s total = 26s Cover.compile + 13s Cover.execute + 5s tests

note: These time are all much faster because it’s local on a multicore laptop vs. CI with the default github action runner

Mystery solved and if y’all happen to have any thoughts or experience on how to address things like this in CI, I’d love to hear your thoughts!

My likely next step is to make a --cover Action for the end of CI, so we can run the tests and get feedback as fast as possible without coverage.

Post #23