ruby / ruby/logger

Memory leak when thread is terminated after using logger.with_level

Open
#135 0 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Dominant language
Ruby
Stars
161
Forks
71
Avg merge
3d 22h
Merged PRs (30d)
2

Description

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.

Contributor guide

No contributing guide indexed for this repository

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start by running the reported MemoryProfiler reproduction and inspect Logger#with_level, the level_override hash, and its Fiber.current keys. Determine whether terminated threads or fibers can be released, then add a regression test if a Logger change is warranted; done means the retained memory no longer grows after the threads terminate.

Written by the indexing model from the issue text.

Assessment

Tech stack
ruby
Domain
tooling
Issue type
Bug
Difficulty
5/5
Estimated time
Over a week
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
30/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.