Skip to content

Memory leak when thread is terminated after using logger.with_level #135

@tr4b4nt

Description

@tr4b4nt

Hello. We were debugging a memory leak that appeared in our rails app after we started using with_level method to adjust visibility of some logs. How to reproduce:

require "logger"
require "memory_profiler"

logger = Logger.new $stdout
MemoryProfiler.report do
  100.times { Thread.new { Thread.current[:data] = Array.new(200); logger.with_level(Logger::ERROR) { logger.debug("test") } }.join }
  GC.start
end.pretty_print
# Total allocated: 336800 bytes (400 objects)
# Total retained:  336800 bytes (400 objects)
# ...
# retained memory by class
-----------------------------------
    164000  Array
    114400  Fiber
     50400  Thread
      8000  Proc

All memory is freed if logger.with_level is removed. My guess is that it happens because Logger uses Fiber.current as key in level_override hash to track log level for current fiber. This reference to Fiber.current is never cleared so GC cannot free connected terminated threads.

For more context this is why it happened in our rails application - we are deployed in kubernetes and have small plugin in puma to process liveness and readiness probes (simple http requests to specific endpoints). One of these requests checks connection to database via simple query. We hide these queries from logs via logger.with_level(Logger::Error) .... Problem was that our puma plugin options had min_threads: 0, max_threads: 1 so puma terminated (and later created again) its thread from time to time, which lead to level_override filling up with old Fiber.current for terminated threads.

When we eventually figured this out the fix was to just keep min_threads same as max_threads in puma.

I am not sure what would be the best way to prevent it (Fiber local variable instead of hash?) or if even something should be changed in Logger, because I realize that our problem was most likely quite unusual. If you think that this should be fixed I would be happy to prepare the change if you point me to the right direction. If not then this could at least help someone who is searching for similar problem.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions