[Proposal] Logger configuration flag to lazily evaluate input

[Jake Mitchell]

Purpose

Optimize slow logging calls, especially in dependencies that might violate logging best practices.

Current best practice

When a Logger.debug call, for instance, is passed an input that's expensive to compute the best practice is to wrap it in a thunk (zero argument function). That way, if the application's current log level is higher than :debug the computation can be skipped. This approach works regardless of whether the logger call was purged at compile-time using :compile_time_purge_level.

Example

The following may be slow due to inspect.

Logger.debug "my_fun/1: input: #{inspect input}"

An optimized version:

Logger.debug fn ->
  "my_fun/1: input: #{inspect input}"
end

Proposal

Add a new Logger application configuration setting, say :lazy, which makes all the Logger macros wrap their chardata_or_fun input in a thunk. We could use an is_function guard to avoid wrapping inputs that are already thunks, but it's not strictly necessary; nested thunks already repeatedly evaluate until they reach a non-thunk.

To maintain current behavior this new parameter would be disabled by default. However, it's worth considering whether the potential cost of hidden, suboptimal logging calls are greater than the cost of calling one thunk per logging call. Before I learned the best practice the problem apparent in my own package which calls Logger.debug thousands of times in an expensive recursive function (see "Logging: a silent performance killer"). It's conceivable that many packages aren't following the best practice, and that the performance degradation is more often death by a thousand cuts than a centralized and noticeable issue like mine was.

If, for whatever reason, this proposal isn't accepted another avenue for improvement is detecting suboptimal Logger calls through static analysis. This could mean having elixirc emit warnings or adding checks to a 3rd party linter. I already opened a proposal with Credo.

[José Valim]

The problem with auto-thunking is that it changes the semantic of the code and it is not enough when the bulk of the expensive work is done outside of the Logger call. For example this would be enough for auto-thunking to not work:

message = "my_fun/1: input: #{inspect input}"

Logger.debug message

We already have a similar behaviour to auto-thunking, which is the compile time purging. If you are sure you are not going to run :debug in production, you can erase all Logger calls and their arguments from ever being evaluated. Your option gives the ability to still revert to :debug but that feels like a small change to make the new option worth it.

If we really want to change how people use Logger, we should probably start by rewriting the documentation to use the function format and explain the non-function format in a later section.

José Valim

www.plataformatec.com.br

Skype: jv.ptec

Founder and Director of R&D

--
You received this message because you are subscribed to the Google Groups "elixir-lang-core" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elixir-lang-core+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elixir-lang-core/64a8c3d6-7ee3-4578-9d17-98979db5cf65%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Jake Mitchell]

On Friday, January 13, 2017 at 10:54:18 AM UTC-8, José Valim wrote:

The problem with auto-thunking is that it changes the semantic of the code and it is not enough when the bulk of the expensive work is done outside of the Logger call. For example this would be enough for auto-thunking to not work:

message = "my_fun/1: input: #{inspect input}"

Logger.debug message

I concede the proposal doesn't solve every possible suboptimal call. However, it trades the cost of evaluating thunks for protection from the risk that a dependency, direct or indirect, has or eventually introduces a subset of the possible suboptimal logging calls. I'm ambivalent about :lazy's default value, but I think the option to enable it is valuable for anyone willing to make this trade-off.

We already have a similar behaviour to auto-thunking, which is the compile time purging. If you are sure you are not going to run :debug in production, you can erase all Logger calls and their arguments from ever being evaluated. Your option gives the ability to still revert to :debug but that feels like a small change to make the new option worth it.

Unless there are built-in mechanisms to control logging levels per package or module (maybe there are?), respectfully I still think :lazy is worth having. As I understand it :compile_time_purge_level's scope includes a project and all its dependencies. There's no way to have X level log purging only for the code in a project and Y level purging for the code in the project's dependencies without custom support for that from each dependency, is there?

If we have that feature I would agree :lazy isn't compelling. However, if Elixir doesn't and won't likely have such a feature, I'd very much like to have :lazy. I can open a new proposal if you like the idea of finer logging control and Elixir doesn't already have it.

If we really want to change how people use Logger, we should probably start by rewriting the documentation to use the function format and explain the non-function format in a later section.

Yes, I agree. I'm happy to contribute after the fate of this proposal is decided.

Would it also be worth emitting warnings for suboptimal calls detected at compile-time?

José Valim

www.plataformatec.com.br

Skype: jv.ptec

Founder and Director of R&D

On Fri, Jan 13, 2017 at 7:41 PM, Jake Mitchell <jacob.d....@gmail.com> wrote:

Purpose

Optimize slow logging calls, especially in dependencies that might violate logging best practices.

Current best practice

When a Logger.debug call, for instance, is passed an input that's expensive to compute the best practice is to wrap it in a thunk (zero argument function). That way, if the application's current log level is higher than :debug the computation can be skipped. This approach works regardless of whether the logger call was purged at compile-time using :compile_time_purge_level.

Example

The following may be slow due to inspect.

Logger.debug "my_fun/1: input: #{inspect input}"

An optimized version:

Logger.debug fn ->
  "my_fun/1: input: #{inspect input}"
end

Proposal

Add a new Logger application configuration setting, say :lazy, which makes all the Logger macros wrap their chardata_or_fun input in a thunk. We could use an is_function guard to avoid wrapping inputs that are already thunks, but it's not strictly necessary; nested thunks already repeatedly evaluate until they reach a non-thunk.

To maintain current behavior this new parameter would be disabled by default. However, it's worth considering whether the potential cost of hidden, suboptimal logging calls are greater than the cost of calling one thunk per logging call. Before I learned the best practice the problem apparent in my own package which calls Logger.debug thousands of times in an expensive recursive function (see "Logging: a silent performance killer"). It's conceivable that many packages aren't following the best practice, and that the performance degradation is more often death by a thousand cuts than a centralized and noticeable issue like mine was.

If, for whatever reason, this proposal isn't accepted another avenue for improvement is detecting suboptimal Logger calls through static analysis. This could mean having elixirc emit warnings or adding checks to a 3rd party linter. I already opened a proposal with Credo.

--
You received this message because you are subscribed to the Google Groups "elixir-lang-core" group.

To unsubscribe from this group and stop receiving emails from it, send an email to elixir-lang-co...@googlegroups.com.

[José Valim]

> Unless there are built-in mechanisms to control logging levels per package or module (maybe there are?), respectfully I still think :lazy is worth having. As I understand it :compile_time_purge_level's scope includes a project and all its dependencies. There's no way to have X level log purging only for the code in a project and Y level purging for the code in the project's dependencies without custom support for that from each dependency, is there?

Sorry but I fail to see how the compile time level purging being per project or per module would make a difference. While we surely can provide such feature, the lazy approach would have the exact same trade-offs?

The only difference between lazy and compile time purging is if you are changing log levels during production. If you are not, then they have the exact same behaviour?

José Valim

www.plataformatec.com.br

Skype: jv.ptec

Founder and Director of R&D

[Jacob Mitchell]

Sorry but I fail to see how the compile time level purging being per project or per module would make a difference. While we surely can provide such feature, the lazy approach would have the exact same trade-offs?

Yes, having either feature would resolve my concerns.

My original proposal was before I recognized finer grain log purging was a viable solution. Now I prefer that over this lazy logging macros proposal because it offers additional benefits, like less noisy package integration troubleshooting during development.

Let's close this proposal. I can start another one for package and/or module-level log purging at compile time.

[José Valim]

> Let's close this proposal. I can start another one for package and/or module-level log purging at compile time.

+1.

José Valim

www.plataformatec.com.br

Skype: jv.ptec

Founder and Director of R&D

[Jacob Mitchell]

In the meantime, I've opened pull request for the documentation change here: https://github.com/elixir-lang/elixir/pull/5655