Memory leak in 1.9.2-p330?

[Tal Yalon]

[Note: parts of this message were removed to make it a legal post.]

Hi all,

Before I go and submit a bug report, I would appreciate a fresh pair of eyes
hopefully finding a bug in the code and not in Ruby

The code pushes elements to a "time window" queue of 2 seconds. Although I
see that the maximum queue size stabilizes after a very short time (couple
of seconds), the process's max RSS size starts to grow after a while 2
minutes.
Interestingly enough, the max RSS size stays fixed when running with 1.8.7.
All tests were done on Ruby compiled using rvm.

Printing the process's RSS and max RSS size was done to observe the leak in
action, This code also leaks when removing the lines that execute ps and
print it.

Any idea will be welcomed.

Thanks,
Tal

#!/usr/bin/env ruby

before = Time.now.to_i
i = 0
max_rss = 0
max_items = 0

queue = []
while true
now = Time.now.to_i
windows_start_time = now - 2
queue << now
while not queue.empty? and queue[0] < windows_start_time
queue.shift
end

if now - before >= 1
max_items = [ max_items, queue.size ].max
rss = `ps -o rss= -p #{Process.pid}`.to_i
max_rss = [ max_rss, rss].max
print("#{now} iters=#{i} queue_size=#{queue.size} rss=#{rss}, max:
queue_size=#{max_items}, rss=#{max_rss}\n")
before = now
end
i += 1
end

 

[Adam Prescott]

[Note: parts of this message were removed to make it a legal post.]

Hi all,

Before I go and submit a bug report, I would appreciate a fresh pair of
eyes
hopefully finding a bug in the code and not in Ruby

The code pushes elements to a "time window" queue of 2 seconds. Although I
see that the maximum queue size stabilizes after a very short time (couple
of seconds), the process's max RSS size starts to grow after a while 2
minutes.
Interestingly enough, the max RSS size stays fixed when running with 1.8.7.
All tests were done on Ruby compiled using rvm.

Printing the process's RSS and max RSS size was done to observe the leak in
action, This code also leaks when removing the lines that execute ps and
print it.

Any idea will be welcomed.

Thanks,
Tal

#!/usr/bin/env ruby

before = Time.now.to_i
i = 0
max_rss = 0
max_items = 0

queue = []
while true
now = Time.now.to_i
windows_start_time = now - 2
queue << now
while not queue.empty? and queue[0] < windows_start_time
queue.shift
end

if now - before >= 1
max_items = [ max_items, queue.size ].max
rss = `ps -o rss= -p #{Process.pid}`.to_i
max_rss = [ max_rss, rss].max
print("#{now} iters=#{i} queue_size=#{queue.size} rss=#{rss}, max:
queue_size=#{max_items}, rss=#{max_rss}\n")
before = now
end
i += 1
end

This is the error I was getting running your code:

/tmp/orig:8: [BUG] Segmentation fault
ruby 1.8.7 (2009-06-12 patchlevel 174) [universal-darwin10.0]

Abort trap

In 1.9 it was running fine, as you said.

I was having some trouble reading your code so I did some tidying to get
this:



time_to_print = Time.now

i = max_rss = max_items = 0

queue = []

while true
start = Time.now
interval = 2 # seconds

queue << start

while !queue.empty? && (Time.now - queue.first) > interval
queue.shift
end

if Time.now - time_to_print >= 0
max_items = [ max_items, queue.size ].max
rss = `ps -o rss= -p #{Process.pid}`.to_i
max_rss = [ max_rss, rss].max
puts "#{start.to_i} iters=#{i} queue_size=#{queue.size} rss=#{rss} max
queue_size=#{max_items} rss=#{max_rss}"
time_to_print = Time.now + 1
end

i += 1
end


The inner conditional chunk uses a Time.now in the comparison against
time_to_print, whereas before it hooked into now and before. It's also using
Time instances and not working off just integers.

However, this code now works fine on 1.8.7 and 1.9, for me.

Maybe this could highlight whatever is causing the bug in 1.8.7 in the
original code? Personally, I'm just more confused as to what might be
causing it!

 

[Tal Yalon]

[Note: parts of this message were removed to make it a legal post.]

Okay,

I ran your code on 1.8.7 (2010-08-16 patchlevel 302) [i686-darwin10.5.0],
and it did not crash, although interestingly enough it did produce the same
leak that I've experienced on 1.9.2-p302!

BTW on my 1.9.2-p302 it didn't ran fine - it didn't crash, but leaked -
exactly which version of 1.9 were you using?

Now, to get things even more interesting, I took your code (that leaked on
both ruby versions I have) and moved the "max_items = [ max_items,
queue.size ].max" line to be before the if() condition. This corrects a
potential bug where max_items would be calculated every second, missing
theoretical spikes in the queue size. Below is the modified code.

Running that code for a few minutes on both versions did _not_ produce any
leak whatsoever... So this is very strange indeed. Can you verify that it
works for you too?

#!/usr/bin/env ruby

time_to_print = Time.now

i = max_rss = max_items = 0

queue = []

while true
start = Time.now
interval = 2 # seconds

queue << start

while !queue.empty? && (Time.now - queue.first) > interval
queue.shift
end

# MOVED max_items CALC TO HERE
max_items = [ max_items, queue.size ].max
if Time.now - time_to_print >= 0
rss = `ps -o rss= -p #{Process.pid}`.to_i
max_rss = [ max_rss, rss].max
puts "#{start.to_i} iters=#{i} queue_size=#{queue.size} rss=#{rss} max
queue_size=#{max_items} rss=#{max_rss}"
time_to_print = Time.now + 1
end

i += 1
end

Hi all,

Before I go and submit a bug report, I would appreciate a fresh pair of
eyes
hopefully finding a bug in the code and not in Ruby

The code pushes elements to a "time window" queue of 2 seconds. Although I
see that the maximum queue size stabilizes after a very short time (couple
of seconds), the process's max RSS size starts to grow after a while 2
minutes.
Interestingly enough, the max RSS size stays fixed when running with 1.8.7.
All tests were done on Ruby compiled using rvm.

Printing the process's RSS and max RSS size was done to observe the leak in
action, This code also leaks when removing the lines that execute ps and
print it.

Any idea will be welcomed.

Thanks,
Tal

#!/usr/bin/env ruby

before = Time.now.to_i
i = 0
max_rss = 0
max_items = 0

queue = []
while true
now = Time.now.to_i
windows_start_time = now - 2
queue << now
while not queue.empty? and queue[0] < windows_start_time
queue.shift
end

if now - before >= 1
max_items = [ max_items, queue.size ].max
rss = `ps -o rss= -p #{Process.pid}`.to_i
max_rss = [ max_rss, rss].max
print("#{now} iters=#{i} queue_size=#{queue.size} rss=#{rss}, max:
queue_size=#{max_items}, rss=#{max_rss}\n")
before = now
end
i += 1
end

This is the error I was getting running your code:

/tmp/orig:8: [BUG] Segmentation fault
ruby 1.8.7 (2009-06-12 patchlevel 174) [universal-darwin10.0]

Abort trap

In 1.9 it was running fine, as you said.

I was having some trouble reading your code so I did some tidying to get
this:



time_to_print = Time.now

i = max_rss = max_items = 0

queue = []

while true
start = Time.now
interval = 2 # seconds

queue << start

while !queue.empty? && (Time.now - queue.first) > interval
queue.shift
end

if Time.now - time_to_print >= 0
max_items = [ max_items, queue.size ].max
rss = `ps -o rss= -p #{Process.pid}`.to_i
max_rss = [ max_rss, rss].max
puts "#{start.to_i} iters=#{i} queue_size=#{queue.size} rss=#{rss} max
queue_size=#{max_items} rss=#{max_rss}"
time_to_print = Time.now + 1
end

i += 1
end


The inner conditional chunk uses a Time.now in the comparison against
time_to_print, whereas before it hooked into now and before. It's also
using
Time instances and not working off just integers.

However, this code now works fine on 1.8.7 and 1.9, for me.

Maybe this could highlight whatever is causing the bug in 1.8.7 in the
original code? Personally, I'm just more confused as to what might be
causing it!