lazily render debug logs #438
Conversation
Without this, `inspect()` is *always* called for every email, regardless of the log level. After this change, `inspect()` only gets called if the log level is debug or more verbose. This can potentially save a massive amount of time depending on the size of the Email struct (and whatever `:assigns`) it has.
|
👍 We had the same issue, caused by inspecting large attachments. |
|
@paulcsmith friendly ping on this PR 👋 Also interested to hear your thoughts on my other questions so I can help fix those too. |
lib/bamboo/mailer.ex
Outdated
|
|
||
| #{inspect(email, limit: :infinity)} | ||
| """) | ||
| #{inspect(email, limit: :infinity)} |
There was a problem hiding this comment.
Good point in the PR description. I think :infinity can be removed 👍
There was a problem hiding this comment.
There are a handful of inspect(email, limit: :infinity) calls in other parts of the library too. Would you prefer to just remove that option entirely, or to set some other value higher than the default of 50?
There was a problem hiding this comment.
I think something higher than 50, but not sure what. Since it is kind of arbitrary, maybe 150? Sounds like a decent in-between. What do you think?
There was a problem hiding this comment.
That seems fine. I changed all the :infinity opts to 150 now ✌️
| @@ -141,19 +141,23 @@ defmodule Bamboo.Mailer do | |||
| end | |||
|
|
|||
| defp debug_sent(email, adapter) do | |||
| Logger.debug(""" | |||
| Sending email with #{inspect(adapter)}: | |||
| Logger.debug(fn -> | |||
There was a problem hiding this comment.
I'm not sure I understand this. If this is a function, does that mean something else needs to call this? Or does Logger.debug accepts a function it will render the debug logs async?
There was a problem hiding this comment.
Logger.debug (or any similar logger function) accepts a function to be dynamically called if the log level is in scope: https://hexdocs.pm/logger/Logger.html#debug/2
Logger.debug "hello?"
Logger.debug fn -> "dynamically calculated debug" end
Logger.debug fn -> {"dynamically calculated debug", [additional: :metadata]} end
|
Oh and about assigns, I think it can be valuable to include because sometimes an assign is missing or not what is expected |
Using infinity can lead to some extremely slow logging when large structs are being passed in. See beam-community#438 for more details.
In our app, we had some emails that were spending a massive amount of time sending, about 50-60 seconds after the email contents had already been generated. This corresponded with crazy memory and CPU usage.
As a disclaimer, our app has some bad issues with excessive preloads that we are working on fixing. But where that data loading takes a few seconds, sending the email itself was taking an additional minute. It took me some digging to find out that the delay was happening between the call to our mailer and the adapter.
Without this change,
inspect()is called for every email, regardless of the log level. After this change,inspect()only gets called if the log level is:debug.Two additional concerns I wanted to discuss:
:assignsare passed along as part of the%Email{}even after rendering has completed. This is whyinspect()is so expensive, because we have a lot of nesting of data structs that are being inspected and logged. Is there any reason thatdeliver_now()anddeliver_later()couldn't strip the:assignsfrom theEmailbefore doing anything extra with them? Since the email has already rendered at this point, it doesn't seem like they serve much purpose.limit: :infinityas part of the debug call? That turns this into a potentially severe issue, whereas it normally might not matter much if just part of a deeply nested dataset is logged.