Logger: when to use an anonymous function

tompave

I am looking for some extra info and examples on when to use the Logger with functions instead of binaries. I’ve read that the function version is lazily evaluated and useful when the log statement could be ignored.

For example, Dave Thomas writes in Programming Elixir 1.2 (chapter 13):

The basic logging functions are Logger.debug, .info, .warn, and .error. Each function takes either a string or a zero-arity function:
Logger.debug "Order total #{total(order)}"
Logger.debug fn -> "Order total #{total(order)}" end
Why have the function version? Perhaps the calculation of the order total is expensive. In the first version, we’ll always call it to interpolate the value into our string, even if the runtime log level is set to ignore debug-level messages. In the function variant, though, the total function will be invoked only if the log message is needed.

This seems to contradict other things I’ve learned as I’m getting more familiar with the language.
For example I’m aware that Logger.info/2 and friends are implemented as macros and the fact that, even though originally it was to get the caller metadata, this allows to remove logging calls that would not be used with the current log level (depending on the value compile_time_purge_level).

Now, since the interface is already made of macros, the binary messages should be lazily evaluated. That is, if Logger.info/2 was a function, the arguments would be evaluated first. Since it’s a macro that returns a quoted expression, the argument will be evaluated later. More precisely, when we hand it over to the Logger.bare_log/3 function.

What’s the purpose of using a function, then? Is it to keep the evaluation lazy even when we change the log level at runtime? How often does that happen though? I’d expect that the expensive log calls will have been already purged through compile_time_purge_level.

4 comments

#logging #macros

1 3975 4

2020-03-11 22:12:01 UTC

Showing Posts 1 to 4

Show Best Posts
Show All (oldest first)
Show All (newest first)

benwilson512

Author of Craft GraphQL APIs in Elixir with Absinthe

Since it’s a macro that returns a quoted expression, the argument will be evaluated later.

This is not correct. The only thing that being a macro does is give Logger the opportunity to purge at compile time. If you do not do that then it leaves the AST largely alone, and then at runtime it’s evaluated just as you would expect.

Logger COULD always wrap the argument in an anonymous function so that it was always lazy, but this could produce quite a bit of unexpected behaviour for people, so it is not what is done

Plenty of people forego compile_time_purge_level because they want to be able to alter the log level dynamically. If the debug values are compile time purged then even if you change the log level while it’s running the debug calls won’t happen. If you wrap expensive debug calls in an anonymous function, then you can switch to debug logging and get the values dynamically

Post #1

tompave

Hi @benwilson512, thank you for the answer.

Logger COULD always wrap the argument in an anonymous function so that it was always lazy, but this could produce quite a bit of unexpected behaviour for people, so it is not what is done

Plenty of people forego compile_time_purge_level because they want to be able to alter the log level dynamically. If the debug values are compile time purged then even if you change the log level while it’s running the debug calls won’t happen. If you wrap expensive debug calls in an anonymous function, then you can switch to debug logging and get the values dynamically

I see, this makes sense.

Since it’s a macro that returns a quoted expression, the argument will be evaluated later.

This is not correct. The only thing that being a macro does is give Logger the opportunity to purge at compile time. If you do not do that then it leaves the AST largely alone, and then at runtime it’s evaluated just as you would expect.

I guess this is the bit I’m still not sure about.
For example, with this simple test I can see that the evaluation is deferred and only executed when necessary:

defmodule NaiveLogger do
  def do_log(level, message) do
    IO.puts "log[#{level}] : #{message}"
  end

  defmacro log(level, message) do
    if level > 2 do
      quote do
        NaiveLogger.do_log(unquote(level), unquote(message))
      end
    else
      :ok
    end
  end
end

give_me_the_message = fn() ->
  IO.puts "I'm being executed!"
  "something is happening"
end


require NaiveLogger

NaiveLogger.log(3, "message: #{give_me_the_message.()}")
# I'm being executed!
# log[3] : message: something is happening
# :ok

NaiveLogger.log(1, "message: #{give_me_the_message.()}")
# :ok

Were you referring to something different, or have I missed a step?

Post #2

benwilson512

Author of Craft GraphQL APIs in Elixir with Absinthe

What you have is exactly what happens with compile time purge on, but is not what happens when compile time purge is off. Your check of the log level happens at compile time which makes it impossible to change dynamically at runtime.

Post #3