Logger docs: recommend using thunks for expensive computations #5655

jmitchell · 2017-01-14T03:17:25Z

In a mailing list conversation we decided Logger docs should encourage lazily evaluated messages over potentially expensive computations that might not get used. This change aims to do that.

In a mailing list conversation we decided Logger docs should encourage lazily evaluated messages over potentially expensive computations that might not get used. This change aims to do that. [0] https://groups.google.com/d/msg/elixir-lang-core/LNZNyUGTdno/9PpvJ8htCQAJ

jmitchell · 2017-01-14T03:20:07Z

lib/logger/lib/logger.ex

+      option, the argument passed to `Logger` calls is evaluated even if the
+      level of the call is lower than `:level`. For expensive to compute
+      messages it's a good idea to wrap them in a zero argument function, so the
+      computation only occurs when this option demands it.


The only addition here is the last sentence. I rewrapped it to 80-columns because that's how the rest of the file seemed to be formatted.

I noticed the Writing Documentation page doesn't suggest any column wrapping conventions.

Please let's not wrap here. We don't have a convention of wrapping at a specific column and this block of text doesn't look to wide to me to justify rewrapping it completely.

whatyouhide · 2017-01-14T11:14:03Z

lib/logger/lib/logger.ex

+      option, the argument passed to `Logger` calls is evaluated even if the
+      level of the call is lower than `:level`. For expensive to compute
+      messages it's a good idea to wrap them in a zero argument function, so the
+      computation only occurs when this option demands it.


Please let's not wrap here. We don't have a convention of wrapping at a specific column and this block of text doesn't look to wide to me to justify rewrapping it completely.

whatyouhide · 2017-01-14T11:16:09Z

lib/logger/lib/logger.ex

+      too. Note that, unlike what happens with the `:compile_time_purge_level`
+      option, the argument passed to `Logger` calls is evaluated even if the
+      level of the call is lower than `:level`. For expensive to compute
+      messages it's a good idea to wrap them in a zero argument function, so the


We could say:

[...] the argument passed to Logger calls is evaluated even if the level of the call is lower than :level. For this reason, messages that are expensive to compute should be wrapped in 0-arity anonymous functions that are evaluated only when the :level option demands it.

Wdyt?

That's clearer--I'll go with this. 👍

whatyouhide · 2017-01-14T11:17:40Z

lib/logger/lib/logger.ex

@@ -19,6 +19,27 @@ defmodule Logger do
    * Wraps OTP's `error_logger` to prevent it from
      overflowing.

+  A common use case is tracking when an important function is called.


I don't think we should say this. I don't think "tracking when an important function is called" is a particularly common use case of Logger (or at least, I think it's the more general "tracking when an event of interest happens in your system").

Good point. How's this?

Logging is useful for tracking when an event of interest happens in
your system. For example, logging incoming synchronous calls in a
GenServer behaviour can provide valuable insight.

def handle_call(request, from, state) do Logger.info fn -> "handle_call/3: #{inspect request} request received " <> "from #{inspect from} with state #{inspect state}." end # ... end

whatyouhide · 2017-01-14T11:19:48Z

lib/logger/lib/logger.ex

+      end
+
+  The `Logger.info/2` macro emits the provided message at the `:info`
+  level. There are additional macros for other levels. Refer to the `:level` and


We can omit mentioning :level and :compile_time_purge_level IMO because they're really close in the next section, and doing so will bring down the noise a bit here.

whatyouhide · 2017-01-14T11:20:26Z

lib/logger/lib/logger.ex

+  `:compile_time_purge_level` configuration options for more details on how
+  levels work.
+
+  Notice the argument passed to `Logger.info` in the above example is a zero


I would put this in the same paragraph as the sentence above ("The Logger.info/2 macro ...").

whatyouhide · 2017-01-14T11:27:52Z

lib/logger/lib/logger.ex

+  wrapped in functions, it's not recommended in this case. Calling `"... #{inspect
+  problem}"` without wrapping it in a zero argument function will hurt
+  performance, even when then `:info` level is blocked by the configured runtime
+  logging level.


What about this rephrasing:

Although the Logger macros accept messages as strings as well as functions, it's recommended to use functions whenever the message is expensive to compute. In the example above, the message will be evaluated (and thus the interpolation inside it) whatever the level is, even if the message will not be actually logged at runtime; the only way of avoiding evaluation of such message is purging the log call at compile-time through the :compile_time_purge_level option (see below), or using a function that is evaluated to generate the message only if the message needs to be logged according to the runtime level.

I am not sure this is an improvement though, wdyt?

I like that a lot better. Phrasing what's recommended as a positive statement is clearer. It also concisely draws a connection to :compile_time_purge_level.

whatyouhide · 2017-01-14T11:28:32Z

Great job @jmitchell, I left a few comments 💟

jmitchell · 2017-01-14T22:13:22Z

Thanks for your feedback and suggestions, @whatyouhide! The latest commit incorporates them.

whatyouhide · 2017-01-14T23:27:41Z

lib/logger/lib/logger.ex

+          "from #{inspect from} with state #{inspect state}."
+        end
+        # ...
+      end


I would keep this example more abstract (since there are tools to inspect messages and calls in GenServer and other OTP behaviours). What about something very abstract like:

def delete_user(user) do Logger.info fn -> "Deleting user from the system: #{inspect(user)}" end end

?

Oops, my latest push missed the inspect part. Fixing now.

whatyouhide

Awesome job @jmitchell! 💟

jmitchell · 2017-01-15T15:35:58Z

Same to you! It's a lot better thanks to your suggestions. 💖

josevalim · 2017-01-15T16:02:40Z

❤️ 💚 💙 💛 💜

jmitchell commented Jan 14, 2017

View reviewed changes

lexmag requested a review from whatyouhide January 14, 2017 11:10

whatyouhide requested changes Jan 14, 2017

View reviewed changes

Logger docs: incorporate initial feedback from elixir-lang#5655.

bcd2a71

whatyouhide reviewed Jan 14, 2017

View reviewed changes

jmitchell added 2 commits January 14, 2017 15:32

Logger docs: use a more generic logging example.

1360f9f

Logger docs: add #{inspect(user)} for expensive logging example.

1bc32b8

whatyouhide approved these changes Jan 15, 2017

View reviewed changes

josevalim merged commit f5dad76 into elixir-lang:master Jan 15, 2017

whatyouhide changed the title ~~Logger docs: recommend using thunks for expensive computations.~~ Logger docs: recommend using thunks for expensive computations Jan 15, 2017

Logger docs: recommend using thunks for expensive computations #5655

Logger docs: recommend using thunks for expensive computations #5655

Uh oh!

Conversation

jmitchell commented Jan 14, 2017

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

whatyouhide commented Jan 14, 2017

Uh oh!

jmitchell commented Jan 14, 2017

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

whatyouhide left a comment

Choose a reason for hiding this comment

Uh oh!

jmitchell commented Jan 15, 2017

Uh oh!

josevalim commented Jan 15, 2017

Uh oh!

Uh oh!