From 301d85a957ad7df906108383f07f015f653bb06e Mon Sep 17 00:00:00 2001 From: Jacob Mitchell Date: Fri, 13 Jan 2017 19:08:22 -0800 Subject: [PATCH 1/4] Logger docs: recommend using thunks for expensive computations. 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 --- lib/logger/lib/logger.ex | 35 +++++++++++++++++++++++++++++------ 1 file changed, 29 insertions(+), 6 deletions(-) diff --git a/lib/logger/lib/logger.ex b/lib/logger/lib/logger.ex index 7359ebaa7aa..21510153f84 100644 --- a/lib/logger/lib/logger.ex +++ b/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. + + def solve(problem) do + Logger.info fn -> + "solve/1 called with problem #{inspect problem}" + end + solve(problem, []) + 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 + `: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 + argument function. Although the `Logger` macros accept strings which aren't + 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. + ## Levels The supported levels are: @@ -83,12 +104,14 @@ defmodule Logger do `config/config.exs`) but also changed dynamically during runtime via `Logger.configure/1`. - * `:level` - the logging level. Attempting to log any message - with severity less than the configured level will simply - cause the message to be ignored. Keep in mind that each backend - may have its specific level, 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`. + * `:level` - the logging level. Attempting to log any message with severity + less than the configured level will simply cause the message to be + ignored. Keep in mind that each backend may have its specific level, + 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 + computation only occurs when this option demands it. * `:utc_log` - when `true`, uses UTC in logs. By default it uses local time (i.e., it defaults to `false`). From bcd2a71b1eaa35ab5ee69ced96bd1d88e45a0be6 Mon Sep 17 00:00:00 2001 From: Jacob Mitchell Date: Sat, 14 Jan 2017 14:09:12 -0800 Subject: [PATCH 2/4] Logger docs: incorporate initial feedback from #5655. --- lib/logger/lib/logger.ex | 50 ++++++++++++++++++++++------------------ 1 file changed, 28 insertions(+), 22 deletions(-) diff --git a/lib/logger/lib/logger.ex b/lib/logger/lib/logger.ex index 21510153f84..07ea70145e1 100644 --- a/lib/logger/lib/logger.ex +++ b/lib/logger/lib/logger.ex @@ -19,26 +19,31 @@ 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. + 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 solve(problem) do + def handle_call(request, from, state) do Logger.info fn -> - "solve/1 called with problem #{inspect problem}" + "handle_call/3: #{inspect request} request received " <> + "from #{inspect from} with state #{inspect state}." end - solve(problem, []) + # ... 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 - `: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 - argument function. Although the `Logger` macros accept strings which aren't - 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. + level. There are additional macros for other levels. Notice the argument + passed to `Logger.info` in the above example is a zero argument function. + + 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. ## Levels @@ -104,14 +109,15 @@ defmodule Logger do `config/config.exs`) but also changed dynamically during runtime via `Logger.configure/1`. - * `:level` - the logging level. Attempting to log any message with severity - less than the configured level will simply cause the message to be - ignored. Keep in mind that each backend may have its specific level, - 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 - computation only occurs when this option demands it. + * `:level` - the logging level. Attempting to log any message + with severity less than the configured level will simply + cause the message to be ignored. Keep in mind that each backend + may have its specific level, 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 this reason, messages that are expensive to + compute should be wrapped in 0-arity anonymous functions that are + evaluated only when the `:label` option demands it. * `:utc_log` - when `true`, uses UTC in logs. By default it uses local time (i.e., it defaults to `false`). From 1360f9fd273e7e6a3425bc73995c9e8dc4a24879 Mon Sep 17 00:00:00 2001 From: Jacob Mitchell Date: Sat, 14 Jan 2017 15:32:28 -0800 Subject: [PATCH 3/4] Logger docs: use a more generic logging example. --- lib/logger/lib/logger.ex | 8 +++----- 1 file changed, 3 insertions(+), 5 deletions(-) diff --git a/lib/logger/lib/logger.ex b/lib/logger/lib/logger.ex index 07ea70145e1..3c7cddd44da 100644 --- a/lib/logger/lib/logger.ex +++ b/lib/logger/lib/logger.ex @@ -20,13 +20,11 @@ defmodule Logger do overflowing. 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. + system. For example, it may be helpful to log whenever a user is deleted. - def handle_call(request, from, state) do + def delete_user(user) do Logger.info fn -> - "handle_call/3: #{inspect request} request received " <> - "from #{inspect from} with state #{inspect state}." + "Deleting user from the system: #{user}" end # ... end From 1bc32b8ff9dec581274d3d8ec60da05662454170 Mon Sep 17 00:00:00 2001 From: Jacob Mitchell Date: Sat, 14 Jan 2017 15:34:51 -0800 Subject: [PATCH 4/4] Logger docs: add `#{inspect(user)}` for expensive logging example. --- lib/logger/lib/logger.ex | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/logger/lib/logger.ex b/lib/logger/lib/logger.ex index 3c7cddd44da..c9151f9dba6 100644 --- a/lib/logger/lib/logger.ex +++ b/lib/logger/lib/logger.ex @@ -24,7 +24,7 @@ defmodule Logger do def delete_user(user) do Logger.info fn -> - "Deleting user from the system: #{user}" + "Deleting user from the system: #{inspect(user)}" end # ... end