Mysterious memory hogging from Logger (100MB+)

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?

2 Likes