TLDR: :compile_time_purge_level
and dependency compilation are your friends.
Moments ago I published my first Elixir package on hex! While testing trying it out from a new project I discovered it was performing ~20x slower than expected, and I’ve figured out why.
First some context: my nascent package backtrex
provides easy access to the backtracking algorithm as a behaviour. For verification purposes it currently includes Sudoku puzzle and solver modules.
If you want to follow along, make a new project, add {:backtrex, "~> 0.1.0"}
to the dependency list, and run mix deps.get
. Then add the following to the top-level lib file:
alias Backtrex.Examples.Sudoku.Puzzle
alias Backtrex.Examples.Sudoku.Solver
@doc """
## Examples
iex> TmpBdemo.hello
true
"""
def hello do
{:ok, puzzle} = Puzzle.from_list([
[5, 3, :_, :_, 7, :_, :_, :_, :_],
[6, :_, :_, 1, 9, 5, :_, :_, :_],
[:_, 9, 8, :_, :_, :_, :_, 6, :_],
[8, :_, :_, :_, 6, :_, :_, :_, 3],
[4, :_, :_, 8, :_, 3, :_, :_, 1],
[7, :_, :_, :_, 2, :_, :_, :_, 6],
[:_, 6, :_, :_, :_, :_, 2, 8, :_],
[:_, :_, :_, 4, 1, 9, :_, :_, 5],
[:_, :_, :_, :_, 8, :_, :_, 7, 9]])
{:ok, expected_solution} = Puzzle.from_list([
[5, 3, 4, 6, 7, 8, 9, 1, 2],
[6, 7, 2, 1, 9, 5, 3, 4, 8],
[1, 9, 8, 3, 4, 2, 5, 6, 7],
[8, 5, 9, 7, 6, 1, 4, 2, 3],
[4, 2, 6, 8, 5, 3, 7, 9, 1],
[7, 1, 3, 9, 2, 4, 8, 5, 6],
[9, 6, 1, 5, 3, 7, 2, 8, 4],
[2, 8, 7, 4, 1, 9, 6, 3, 5],
[3, 4, 5, 2, 8, 6, 1, 7, 9]])
{:ok, :solution, solution} = puzzle |> Solver.solve
solution == expected_solution
end
Finally run mix test
.
Ahhh, that’s a lot of logs!! Go to the config/config.exs
and add config :logger, level: :warn
to silence them. Peace and quiet.
If the test passes, kiss your machine for me. At least on my dev VM it fails because it doesn’t finish within the 60-second timeout. In any case it’s taking far too long.
As you probably gathered from the TLDR, the solution ends up being to tell mix to purge the logs below :warn
as well:
config :logger,
level: :warn,
compile_time_purge_level: :warn
AND run this before running mix test
again.
$ mix do deps.clean backtrex, deps.get, deps.compile
Okay, now it should pass within 5 seconds or so. Out of curiosity I increased the test timeout and ran the test again under the previous configuration. It takes up to 80 seconds to finish. Quite a difference.
Questions
- How, if at all, can I keep any of the logs in my package source and still deliver a good user experience?
- Those of you with code in production: how sure are you that potentially unused logging calls in your (or your dependencies’) BEAM files aren’t killing your performance? I think if you diligently set an aggressive
:compile_time_purge_level
in your project’s config and carefully recompiled your dependencies you’ll be fine.