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

1. How, if at all, can I keep any of the logs in my package source and still deliver a good user experience?
2. 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.