Memory leak in 1.9.2-p330?

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 :slight_smile:

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!

路路路

On Tue, Feb 8, 2011 at 3:07 PM, Tal Yalon <tal.yalon@gmail.com> wrote:

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 :slight_smile:

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

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

路路路

On Tue, Feb 8, 2011 at 7:57 PM, Adam Prescott <mentionuse@gmail.com> wrote:

On Tue, Feb 8, 2011 at 3:07 PM, Tal Yalon <tal.yalon@gmail.com> wrote:

> 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 :slight_smile:
>
> 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!