Mongrel 0.3.13.4 Pre-Release -- Ruby's LEAK Fixed (Death To

Ruby
21

On Aug 26, 2006, at 11:04 PM, M. Edward (Ed) Borasky wrote:

  1. Deleting references to no-longer-needed objects and then explicitly
    calling the garbage collector has a longer history and tradition than
    UNIX. It is “standard software engineering practice” in any
    environment
    that has garbage collection. Just last week, I had to stick such a
    call
    into an R program to keep it from crashing (on a Windows machine
    with 2
    GB of RAM!)

Indeed.

So, instead of just counting the live objects, I decided to take a
look at what was there.

Guess what I found.

Using Ara’s test and mutex, I was getting a kind of oscillation of
memory use. Not a nice profile at all. Having a look at the objects
still in ObjectSpace what do I see? why the Thread objects! I was
running Ara’s test with 100 threads and there was 101 threads in
ObjectSpace (well, sometimes 103).

So I set the guard to nil before running the cleanup step, and
created a new mutex at the beginning of the iteration. Now only one
Thread in the ObjectSpace. And guess what? A nice constant memory
utilisation (according to VSZ).

The Mutex was somehow holding the Thread object in memory and that
was holding other stuff.

You’re right, deleting references to no-longer-needed objects is
standard. I suppose it is also standard to make sure you get all of
them :slight_smile:

Cheers,
Bob

Bob H. – blogs at <http://www.recursive.ca/
hutch/>
Recursive Design Inc. – http://www.recursive.ca/
Raconteur – http://www.raconteur.info/
xampl for Ruby – http://rubyforge.org/projects/xampl/

22

On Mon, 28 Aug 2006 [email protected] wrote:

with those mods my results are largely the same: mutex shows no leak at all
and sync show a gradual trend up. with respect to sync, however, the trend
is from a small amount of initial memory and it may well be the case that it
eventually gets cleared so i am not asserting a leak in sync at this point -
i’m doing a long run to see which is the case.

after a few hours i’ve finally seen the sync code cycle down after
growing
slowly for a looooong time, so it does not appear to have a leak either.

except from output:

iter: 449
threads loaded in 23.4420.
memory_usage : pct_mem: 44.0%, vsz: 453944b, rss: 452456b
n_threads_in_object_space : 421
threads killed.
memory_usage : pct_mem: 22.3%, vsz: 230740b, rss: 229380b
n_threads_in_object_space : 1

iter: 450
threads loaded in 23.2819.
memory_usage : pct_mem: 44.0%, vsz: 453776b, rss: 452372b
n_threads_in_object_space : 421
threads killed.
memory_usage : pct_mem: 22.3%, vsz: 230740b, rss: 229380b
n_threads_in_object_space : 1

iter: 451
threads loaded in 23.4827.
memory_usage : pct_mem: 44.0%, vsz: 453776b, rss: 452416b
n_threads_in_object_space : 421
threads killed.
memory_usage : pct_mem: 8.0%, vsz: 83740b, rss: 82380b
n_threads_in_object_space : 1

iter: 452
threads loaded in 23.3958.
memory_usage : pct_mem: 44.1%, vsz: 454336b, rss: 452932b
n_threads_in_object_space : 421
threads killed.
memory_usage : pct_mem: 8.5%, vsz: 89336b, rss: 87976b
n_threads_in_object_space : 1

iter: 453
threads loaded in 23.4515.
memory_usage : pct_mem: 44.0%, vsz: 454300b, rss: 452856b
n_threads_in_object_space : 421
threads killed.
memory_usage : pct_mem: 9.4%, vsz: 98472b, rss: 97116b
n_threads_in_object_space : 1

cheers.

-a

23

On Sun, 27 Aug 2006, Daniel M. wrote:

To look at how much total memory is used, the variable you want is
VSZ, which isn’t available in a “ps v” but is in a “ps u”. I modified
your script to look at the %MEM, VSZ, and RSS numbers from “ps u” and
also to run GC.start a variable number of times.

good catch! i’m tweaking my script now…

-a

24

On Sun, 27 Aug 2006 [email protected] wrote:

On Sun, 27 Aug 2006 [email protected] wrote:

I have been playing with this all morning.

me too :wink: i took a few pages from your book and included some of the
other
suggestions before re-running the tests.

before i dump all the output i’ll summarize:

  • the script new counts threads in objectspace before/after thread
    creation/deletion

  • time to create/kill threads under mutex/sync is tracked

  • memory usage is tracked via pct_mem, vsz, and rss

  • no gc voodoo, gc is run only once :wink:

  • no waiting on Thread.list. it’s assumed the kill works.

with those mods my results are largely the same: mutex shows no leak at
all
and sync show a gradual trend up. with respect to sync, however, the
trend is
from a small amount of initial memory and it may well be the case that
it
eventually gets cleared so i am not asserting a leak in sync at this
point -
i’m doing a long run to see which is the case. one strange thing, while
it’s
the sync code that shows a gradual trend up - it also seems to result in
better cycling of threads through object space - which is to say all
threads
seem to actually get killed instantly with sync while with mutex some
stick
around (but are eventually cleared). this may well be a timing issue as
kirk
suggested. in both cases there is not trend up - just different cycles.

one important note - while making my mods i manged to make both
mutex/sync
leak by accidentally holding a reference to the created threads. of
course
it’s not either lib that was leakingbut my own damn code! it’s still my
feeling that any perceived leak is due to programmer error but, as i
said, the
verdict is still out on sync for me…

here’s the code and output from 10 iterations using 420 threads under
both
mutex and sync:

harp:~ > cat a.rb
require ‘thread’
require ‘sync’

class TestThreads
def initialize which, n, iter
c = case which
when /mutex/io
Mutex
when /sync/io
Sync
end
@guard = c.new
@n = Integer n
@iter = Integer iter
puts “using: #{ c.name }”
puts “n: #{ @n }”
puts “iter: #{ @iter }”
end

def memory_usage
stdout = ps u #{ Process.pid }
last_line = stdout.split(%r/\n/).last.strip
fields = last_line.split(%r/\s+/)
v = fields[3,3]
suffixes = %w( % b b )
prefixes = %w( pct_mem vsz rss )
prefixes.map{|k| “#{ k }: #{ v.shift }#{ suffixes.shift }”}.join ',
’
end

def gc_start!
GC.start
end

def n_threads_in_object_space
(t = 0 and ObjectSpace.each_object{|o| t += 1 if Thread === o} and
t)
end

def tq
q = Queue.new
t = Thread.new{
mb = @guard.synchronize{ 0.chr * (2 ** 20) }
q.push :ready
Thread.stop
}
[t, q]
end

def elapsed
a = Time.now
yield
b = Time.now
b.to_f - a.to_f
end

def run
list = []
@iter.times do |i|
puts “—”
puts “iter: #{ i }”

   e = elapsed{
     # load 1000 threads up
     @n.times{ list << tq }

     # wait for all threads to init memory with mb of data
     list.each{|t,q| q.pop}
   }

   # show memory usage
   gc_start!
   puts "threads loaded in #{ '%4.4f' % e }."
   puts "memory_usage : #{ memory_usage }"
   puts "n_threads_in_object_space : #{ n_threads_in_object_space }"

   # kill all threads
   list.each{|t,q| t.kill}.clear

   # show memory usage
   gc_start!
   puts "threads killed."
   puts "memory_usage : #{ memory_usage }"
   puts "n_threads_in_object_space : #{ n_threads_in_object_space }"
 end

end
end

$VERBOSE = nil
STDOUT.sync = true
Thread.abort_on_exception = true
trap(‘INT’){ exit }

which, n, iter, ignored = ARGV
which ||= ‘mutex’
n ||= 42
iter ||= 4242
TestThreads.new(which, n, iter).run

harp:~ > ruby a.rb mutex 420 10
using: Mutex
n: 420
iter: 10

iter: 0
threads loaded in 24.7623.
memory_usage : pct_mem: 44.3%, vsz: 457056b, rss: 455528b
n_threads_in_object_space : 421
threads killed.
memory_usage : pct_mem: 13.3%, vsz: 138208b, rss: 136720b
n_threads_in_object_space : 121

iter: 1
threads loaded in 24.8212.
memory_usage : pct_mem: 44.4%, vsz: 458048b, rss: 456464b
n_threads_in_object_space : 422
threads killed.
memory_usage : pct_mem: 13.5%, vsz: 140616b, rss: 139128b
n_threads_in_object_space : 123

iter: 2
threads loaded in 24.6988.
memory_usage : pct_mem: 44.3%, vsz: 457848b, rss: 455268b
n_threads_in_object_space : 422
threads killed.
memory_usage : pct_mem: 12.9%, vsz: 134452b, rss: 132664b
n_threads_in_object_space : 117

iter: 3
threads loaded in 24.9785.
memory_usage : pct_mem: 44.1%, vsz: 457124b, rss: 453824b
n_threads_in_object_space : 421
threads killed.
memory_usage : pct_mem: 13.3%, vsz: 139572b, rss: 136768b
n_threads_in_object_space : 122

iter: 4
threads loaded in 24.5234.
memory_usage : pct_mem: 44.2%, vsz: 457020b, rss: 454120b
n_threads_in_object_space : 421
threads killed.
memory_usage : pct_mem: 13.5%, vsz: 141616b, rss: 138772b
n_threads_in_object_space : 124

iter: 5
threads loaded in 24.4355.
memory_usage : pct_mem: 44.3%, vsz: 457888b, rss: 455536b
n_threads_in_object_space : 422
threads killed.
memory_usage : pct_mem: 13.3%, vsz: 138532b, rss: 136856b
n_threads_in_object_space : 121

iter: 6
threads loaded in 24.3171.
memory_usage : pct_mem: 44.3%, vsz: 458184b, rss: 455076b
n_threads_in_object_space : 422
threads killed.
memory_usage : pct_mem: 13.3%, vsz: 140256b, rss: 137596b
n_threads_in_object_space : 123

iter: 7
threads loaded in 24.1998.
memory_usage : pct_mem: 44.3%, vsz: 458028b, rss: 455164b
n_threads_in_object_space : 422
threads killed.
memory_usage : pct_mem: 13.2%, vsz: 139228b, rss: 136468b
n_threads_in_object_space : 122

iter: 8
threads loaded in 24.2478.
memory_usage : pct_mem: 44.2%, vsz: 457156b, rss: 453976b
n_threads_in_object_space : 421
threads killed.
memory_usage : pct_mem: 13.3%, vsz: 139228b, rss: 137052b
n_threads_in_object_space : 122

iter: 9
threads loaded in 24.1954.
memory_usage : pct_mem: 44.3%, vsz: 458084b, rss: 455028b
n_threads_in_object_space : 422
threads killed.
memory_usage : pct_mem: 13.8%, vsz: 144472b, rss: 141732b
n_threads_in_object_space : 126

harp:~ > ruby a.rb sync 420 10
using: Sync
n: 420
iter: 10

iter: 0
threads loaded in 26.5464.
memory_usage : pct_mem: 36.5%, vsz: 454628b, rss: 375700b
n_threads_in_object_space : 421
threads killed.
memory_usage : pct_mem: 0.9%, vsz: 11328b, rss: 9276b
n_threads_in_object_space : 1

iter: 1
threads loaded in 25.9357.
memory_usage : pct_mem: 41.4%, vsz: 454524b, rss: 425824b
n_threads_in_object_space : 421
threads killed.
memory_usage : pct_mem: 1.9%, vsz: 23956b, rss: 20180b
n_threads_in_object_space : 1

iter: 2
threads loaded in 25.9797.
memory_usage : pct_mem: 43.3%, vsz: 454600b, rss: 445488b
n_threads_in_object_space : 421
threads killed.
memory_usage : pct_mem: 2.3%, vsz: 31544b, rss: 24364b
n_threads_in_object_space : 1

iter: 3
threads loaded in 24.9242.
memory_usage : pct_mem: 43.8%, vsz: 454316b, rss: 450620b
n_threads_in_object_space : 421
threads killed.
memory_usage : pct_mem: 3.5%, vsz: 39480b, rss: 35952b
n_threads_in_object_space : 1

iter: 4
threads loaded in 24.3832.
memory_usage : pct_mem: 43.9%, vsz: 454396b, rss: 451548b
n_threads_in_object_space : 421
threads killed.
memory_usage : pct_mem: 4.8%, vsz: 52036b, rss: 49352b
n_threads_in_object_space : 1

iter: 5
threads loaded in 24.1944.
memory_usage : pct_mem: 43.9%, vsz: 454596b, rss: 451692b
n_threads_in_object_space : 421
threads killed.
memory_usage : pct_mem: 5.9%, vsz: 63872b, rss: 61260b
n_threads_in_object_space : 1

iter: 6
threads loaded in 24.1334.
memory_usage : pct_mem: 43.9%, vsz: 454388b, rss: 451068b
n_threads_in_object_space : 421
threads killed.
memory_usage : pct_mem: 6.8%, vsz: 73560b, rss: 70336b
n_threads_in_object_space : 1

iter: 7
threads loaded in 24.0867.
memory_usage : pct_mem: 43.8%, vsz: 454252b, rss: 450204b
n_threads_in_object_space : 421
threads killed.
memory_usage : pct_mem: 7.5%, vsz: 81920b, rss: 78000b
n_threads_in_object_space : 1

iter: 8
threads loaded in 24.0251.
memory_usage : pct_mem: 43.8%, vsz: 454356b, rss: 450000b
n_threads_in_object_space : 421
threads killed.
memory_usage : pct_mem: 8.6%, vsz: 92836b, rss: 88532b
n_threads_in_object_space : 1

iter: 9
threads loaded in 24.2115.
memory_usage : pct_mem: 43.9%, vsz: 454260b, rss: 451804b
n_threads_in_object_space : 421
threads killed.
memory_usage : pct_mem: 9.8%, vsz: 103864b, rss: 101528b
n_threads_in_object_space : 1

kind regards.

-a

25

On Sat, 26 Aug 2006, Zed S. wrote:

** This is a Ruby issue, so if you have software using Mutex or Monitor,
change to Sync now. **

Tests of this latest pre-release show that the RAM is properly cycled by
the GC and that it’s actually finally solved. If you run your app using
this release and you still have a leak then use the memory debugging
tools mongrel has to rule out your code (see below).

hi zed-

if you are really serious about fixing your leak i suggest you re-work
your
tests. as i mentioned before they have several race conditions, not
least of
which that they both start a random number of threads, not 1000 as the
code
suggests (you can easily confirm by printing out the number of times the
thread init loop executes). further, sync.rb is the single ruby lib
i’ve had
memory issues with on production systems. i have never managed to
figure out
why that is…

in any case a careful script which allocated memory in a thread, waits
for all
threads to finish allocation, checks memory, and then kills all threads
before
checking again shows some suprising results which you should read
carefully:

using mutex shows a nice cycle of memory freed:

 harp:~ > cat a.rb.mutex
 using: Mutex
 n: 420
 iter: 0
 with 420 threads holding memory : 44.0%
 with 0 threads holding memory : 13.0%
 iter: 1
 with 420 threads holding memory : 43.9%
 with 0 threads holding memory : 13.0%
 iter: 2
 with 420 threads holding memory : 44.1%
 with 0 threads holding memory : 13.3%
 iter: 3
 with 420 threads holding memory : 44.1%
 with 0 threads holding memory : 13.2%
 iter: 4
 with 420 threads holding memory : 44.0%
 with 0 threads holding memory : 13.5%
 iter: 5
 with 420 threads holding memory : 44.1%
 with 0 threads holding memory : 13.2%
 iter: 6
 with 420 threads holding memory : 43.9%
 with 0 threads holding memory : 13.2%
 iter: 7
 with 420 threads holding memory : 44.2%
 with 0 threads holding memory : 13.2%
 iter: 8
 with 420 threads holding memory : 44.1%
 with 0 threads holding memory : 13.5%
 iter: 9
 with 420 threads holding memory : 44.1%
 with 0 threads holding memory : 13.9%

using sync, on the other hand, looks leaky, though i’m not saying it is.

 harp:~ > cat a.rb.sync
 using: Sync
 n: 420
 iter: 0
 with 420 threads holding memory : 43.8%
 with 0 threads holding memory : 1.0%
 iter: 1
 with 420 threads holding memory : 43.8%
 with 0 threads holding memory : 2.0%
 iter: 2
 with 420 threads holding memory : 43.8%
 with 0 threads holding memory : 2.7%
 iter: 3
 with 420 threads holding memory : 43.8%
 with 0 threads holding memory : 3.5%
 iter: 4
 with 420 threads holding memory : 43.8%
 with 0 threads holding memory : 3.8%
 iter: 5
 with 420 threads holding memory : 43.8%
 with 0 threads holding memory : 4.6%
 iter: 6
 with 420 threads holding memory : 43.8%
 with 0 threads holding memory : 5.4%
 iter: 7
 with 420 threads holding memory : 43.8%
 with 0 threads holding memory : 6.4%
 iter: 8
 with 420 threads holding memory : 43.8%
 with 0 threads holding memory : 7.2%
 iter: 9
 with 420 threads holding memory : 43.7%
 with 0 threads holding memory : 8.1%

here is the code, note that it’s quite careful to only create a fixed
number
of threads, to wait for them to each init a mb of memory, and only then
to
check memory usage. likewise for checking after killing all threads -
it’s
done immediately after killing threads and running gc. here is the
code:

 harp:~ > cat a.rb
 require 'thread'
 require 'sync'

 class TestThreads
   def initialize which, n
     c = case which
       when /mutex/io
         Mutex
       when /sync/io
         Sync
     end
     @guard = c.new
     @n = Integer n
     puts "using: #{ c.name }"
     puts "n: #{ @n }"
   end

   def pct_mem # linux specific field pos i'm sure
     stdout = `ps v #{ Process.pid }`
     stdout.split(%r/\n/).last.strip.split(%r/\s+/)[8] + '%'
   end

   def tq
     q = Queue.new
     t = Thread.new{
       mb = @guard.synchronize{ 0.chr * (2 ** 20) }
       q.push :ready
       Thread.stop
     }
     [t, q]
   end

   def run
     list = []
     10.times do |i|
       puts "iter: #{ i }"

       # load 1000 threads up
       @n.times{ list << tq }

       # wait for all threads to init memory with mb of data
       list.each{|t,q| q.pop}

       # show memory usage
       GC.start
       puts "with #{ list.size } threads holding memory : #{ pct_mem

}"

       # kill all threads - clean up
       list.each{|t,q| t.kill}
       list.clear
       sleep 1 until Thread.list.size == 1

       # show memory usage
       GC.start
       puts "with 0 threads holding memory : #{ pct_mem }"
     end
   end
 end

 $VERBOSE = nil
 STDOUT.sync = true
 Thread.abort_on_exception = true
 trap('INT'){ exit }

 which, n, ignored = ARGV
 TestThreads.new(which, n).run

in any case, i’d carefully examine your tests (or the rails code if that
is
indeed what it’s modeled after) to make sure that they test
Mutex/Sync/Thread/Ruby and not your os virtual memory system and look
closely
at the results again - like i said, i have had issues with sync.rb.

the point here is that it is probably the code in question and not Mutex
per
se that was causing your process to grow in vmsize.

regards.

-a

to foster inner awareness, introspection, and reasoning is more
efficient than
meditation and prayer.

  • h.h. the 14th dalai lama