Logging: a silent performance killer

jmitchell

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.

11 comments

#logging #mix #compiler #performance

8 5556 11

2017-03-23 11:00:10 UTC

First 10 of 11 Posts

jmitchell

By the way, I’ve opened a new thread where I’m accepting feedback about the project itself.

Post #1

minhajuddin

Good find
I always assumed that all debug log statements from my code were removed at compile time. I think :compile_time_purge_level should by default follow the Logger level.

:compile_time_purge_level - purges at compilation time all calls that have log level lower than the value of this option. This means that Logger calls with level lower than this option will be completely removed at compile time, accruing no overhead at runtime. Defaults to :debug and only applies to the Logger.debug/2, Logger.info/2, Logger.warn/2, and Logger.error/2 macros (e.g., it doesn’t apply to Logger.log/3. Note that arguments passed to Logger calls that are removed from the AST at compilation time are never evaluated, thus any function call that occurs in these arguments is never executed. As a consequence, avoid code that looks like Logger.debug(“Cleanup: #{perform_cleanup()}”) as in the example perform_cleanup/0 won’t be executed if the :compile_time_purge_level is :info or higher.

Post #2

jwarlander

You could try the following pattern, as per the Logger docs:

Logger.debug fn -> {"expensive to calculate debug", [additional: :metadata]} end

Post #3

jwarlander

Passing funs to the Logger.debug/2 calls in backtrex will, at least on my machine, take mix test down to just below 6 seconds given the example outlined in the initial post above - see pull request for details:

https://github.com/jmitchell/backtrex/pull/1

Post #4

jmitchell

Thank you for your advice and going the extra length to make a pull request. I’ve merged it and verified it resolves logging performance issues even without relying on :compile_time_purge_level.

Post #5

jmitchell

That sounds nice, although I’m not familiar enough yet with when/where Hex dependencies are compiled and/or cached. From my experiments it seemed explicitly recompiling a dependency is necessary for :compile_time_purge_level to have any effect.

Lessons learned

As a package consumer I need a tool that can query a call graph from a project and its dependencies. Of course this assumes I maintain a list of queries I care about. If I were using Backtrex (before @jwarlander’s improvement) I’d use such a tool to query for potentially problematic calls like Logger.debug. In this case I’d expect to get back a report of filenames and line numbers that call Logger.debug, and then I could quickly audit all those lines. Anyone know of a query tool that already does this?

Looking at the problem from the perspective of the package publisher a static analysis tool could have helped detect the problem and suggest a refactoring. I’m already using credo to lint Backtrex’s code, but it doesn’t yet pick up on potentially expensive logging calls. [edit: I’ve submitted a proposal]

Post #6

jmitchell

I also submitted a proposal to the elixir-lang-core list: [Proposal] Logger configuration flag to lazily evaluate input

Post #7

jwarlander

I noted that @josevalim responded; my initial thought about this issue was also that the Logger documentation could be more explicit about the advantage of passing a fun.. Maybe a pull request might be in order?