After experiencing a 1GB memory spike in our production environment without any clear indication why I went down a path trying to understand what happened and noticed that the Logger tends to hog large amounts of memory after interactions with a live-view.
I couldn’t really understand why so I started to disable different logging backends one by one, only to realize that Logger seems to be the culprit.
After a fresh restart of the server, :logger.get_config() returns the following (which is what caused the memory consumption):
%{
primary: %{
level: :debug,
filter_default: :log,
filters: [
logger_process_level: {&Logger.Utils.process_level/2, []},
logger_translator: {&Logger.Utils.translator/2,
%{
otp: true,
sasl: false,
translators: [
{Plug.Cowboy.Translator, :translate},
{Logger.Translator, :translate}
]
}}
],
metadata: %{}
},
proxy: %{
burst_limit_enable: false,
drop_mode_qlen: 1000,
flush_qlen: 5000,
sync_mode_qlen: 500,
overload_kill_restart_after: 5000,
burst_limit_max_count: 500,
burst_limit_window_time: 1000,
overload_kill_enable: false,
overload_kill_mem_size: 3000000,
overload_kill_qlen: 20000
},
handlers: [
%{
id: Phoenix.LiveDashboard.LoggerPubSubBackend,
module: Phoenix.LiveDashboard.LoggerPubSubBackend,
level: :all,
filter_default: :log,
filters: [],
formatter: {Logger.Formatter,
%Logger.Formatter{
template: [:time, " ", :metadata, " [", :level, "] ", :message, "\n"],
truncate: 8096,
metadata: [],
colors: %{
error: :red,
enabled: false,
info: :normal,
warning: :yellow,
debug: :cyan,
notice: :normal,
emergency: :red,
alert: :red,
critical: :red
},
utc_log?: false
}}
},
%{
id: Logger,
module: Logger.Backends.Handler,
config: %{truncate: 8096, utc_log: false, thresholds: {20, 500}},
level: :all,
filter_default: :log,
filters: [],
formatter: {:logger_formatter, %{}}
},
%{
id: :default,
module: :logger_std_h,
config: %{
type: :standard_io,
burst_limit_enable: true,
drop_mode_qlen: 200,
flush_qlen: 1000,
sync_mode_qlen: 10,
overload_kill_restart_after: 5000,
burst_limit_max_count: 500,
burst_limit_window_time: 1000,
overload_kill_enable: false,
overload_kill_mem_size: 3000000,
overload_kill_qlen: 20000,
filesync_repeat_interval: :no_repeat
},
format: "[$level] $message\n",
level: :error,
filter_default: :log,
filters: [remote_gl: {&:logger_filters.remote_gl/2, :stop}],
formatter: {Logger.Formatter,
%Logger.Formatter{
template: [:time, " ", :metadata, " [", :level, "] ", :message, "\n"],
truncate: 8096,
metadata: [],
colors: %{
error: :red,
enabled: true,
info: :normal,
warning: :yellow,
debug: :cyan,
notice: :normal,
emergency: :red,
alert: :red,
critical: :red
},
utc_log?: false
}},
metadata: [:request_id]
},
%{
id: :ssl_handler,
module: :logger_std_h,
config: %{
type: :standard_io,
burst_limit_enable: true,
drop_mode_qlen: 200,
flush_qlen: 1000,
sync_mode_qlen: 10,
overload_kill_restart_after: 5000,
burst_limit_max_count: 500,
burst_limit_window_time: 1000,
overload_kill_enable: false,
overload_kill_mem_size: 3000000,
overload_kill_qlen: 20000,
filesync_repeat_interval: :no_repeat
},
level: :debug,
filter_default: :stop,
filters: [
filter_non_ssl: {&:logger_filters.domain/2, {:log, :sub, [:otp, :ssl]}}
],
formatter: {:ssl_logger, %{}}
}
],
module_levels: [ssl_logger: :debug]
}
After running :logger.remove_handler(Logger) on after a fresh restart and doing the same interactions the consumption seems steady:
At first I thought it was some kind of misconfiguration but after reviewing my config everything seems to be in order (and in line with the documentation in elixir 1.15 release notes):
config :logger, :default_handler,
level: :error,
metadata: [:request_id]
config :logger, :default_formatter,
format: "$time $metadata [$level] $message\n"
After doing some research into logger configuration I’m still in a position where I can’t make any sense of that behaviour.
I’m currently running elixir 1.15.7 and OTP 26.1.2 if anyone happens to know any problem related to those versions.
Anyone got a clue or an idea on where I should be looking next to get ahead of this problem?
