hunting down memory leaks

logging_leak_test.rb

NUM_FORKS      = 15
NUM_ITERATIONS = 250

STDOUT.sync = true

require 'logging'

module Logging
  def self.show_diagnostic_contexts( io = STDOUT )
    Thread.exclusive do
      count = ObjectSpace.each_object(Thread) do |thread|
        io.puts "## [#{Process.pid}] #{thread[:name]} - #{thread.status}"
        io.puts "## MDC: #{thread[MappedDiagnosticContext::NAME].inspect}"
        io.puts "## MDC Stack: #{thread[MappedDiagnosticContext::STACK_NAME].inspect}"
        io.puts "## NDC: #{thread[NestedDiagnosticContext::NAME].inspect}"
        io.puts "## --------"
      end
      io.puts "#### [#{Process.pid}] Found #{count} threads"
      io.puts ObjectSpace.count_objects.inspect
      io.puts '#'*80
    end
  end
end

# log the first and last names of the celebrity with each quote
Logging.appenders.stdout \
  :layout => Logging.layouts.pattern(:pattern => '[%X{pid}](%T) %X{first} %X{last}: %m\n')

# all our threads will have names
Thread.current[:name] = 'main'

log = Logging.logger['User']
log.add_appenders 'stdout'
log.level = :debug

Logging.mdc['pid']   = Process.pid
Logging.mdc['first'] = 'John'
Logging.mdc['last']  = 'Doe'

Thread.new {
  Thread.current[:name] = 'temp1'
  sleep 0.5
}
Thread.new {
  Thread.current[:name] = 'temp2'
  sleep 0.5
}

# let the two temp threads spin up
sleep 0.250
Logging.show_diagnostic_contexts

# capture the child process IDs
pids = []

NUM_FORKS.times do
  pids << fork do
    # ensure we have a clean object space to start with
    GC.start
    Logging.mdc['pid'] = Process.pid

    # log diagnostic context information to this file
    fd = File.open("#{Process.pid}.txt", "w")
    Logging.show_diagnostic_contexts(fd)

    NUM_ITERATIONS.times do |count|
      threads = []

      # in this first thread we will log some quotes by Allan Rickman
      threads << Thread.new do
        Thread.current[:name] = 't1-%03d' % count
        Logging.mdc['first'] = 'Allan'
        Logging.mdc['last']  = 'Rickman'

        # in this second thread we will log some quotes by William Butler Yeats
        threads << Thread.new do
          Thread.current[:name] = 't2-%03d' % count
          Logging.mdc['first']  = 'William'
          Logging.mdc['middle'] = 'Butler'
          Logging.mdc['last']   = 'Yeats'

          # and in this third thread we will log some quotes by Bono
          threads << Thread.new do
            Thread.current[:name] = 't3-%03d' % count
            Logging.mdc['last']  = nil  # otherwise we inherit the last name "Yeats"
            Logging.mdc['first'] = 'Bono'

            [ %q{Music can change the world because it can change people.},
              %q{The less you know, the more you believe.}
            ].each do |quote|
              sleep rand
              log.info quote
            end
          end

          [ %q{Tread softly because you tread on my dreams.},
            %q{The best lack all conviction, while the worst are full of passionate intensity.},
            %q{Education is not the filling of a pail, but the lighting of a fire.},
            %q{Do not wait to strike till the iron is hot; but make it hot by striking.},
            %q{People who lean on logic and philosophy and rational exposition end by starving the best part of the mind.}
          ].each do |quote|
            sleep rand
            log.info quote
          end
        end

        [ %q{I've never been able to plan my life. I just lurch from indecision to indecision.},
          %q{If only life could be a little more tender and art a little more robust.},
          %q{I do take my work seriously and the way to do that is not to take yourself too seriously.},
          %q{I'm a quite serious actor who doesn't mind being ridiculously comic.}
        ].each do |quote|
          sleep rand
          log.info quote
        end
      end

      # this is just to stress the system and try and force a memory leak
      100.times do |n|
        threads << Thread.new do
          Thread.current[:name] = sprintf("%02d-%03d", n, count)
          Logging.mdc['number'] = n
        end
      end

      threads.each { |t| t.join }
      threads.clear    # so we don't hold on to thread references

      Logging.show_diagnostic_contexts(fd)
    end

    # clean up the object space and see if we leaked anything
    GC.start
    Logging.show_diagnostic_contexts(fd)
    fd.close
  end
end

pids.compact!
unless pids.empty?
  pids.each { |pid| Process.wait pid }

  log.info %q{and now we are done}

  Logging.show_diagnostic_contexts
  GC.start
  Logging.show_diagnostic_contexts
end