Memory leaks due to overwritten local variables being wrongly kept alive on the stack #4439

Closed
ivoanjo opened this Issue Jan 13, 2017 · 6 comments

Comments

Projects
None yet
4 participants
@ivoanjo
Contributor

ivoanjo commented Jan 13, 2017

Environment

Running jruby 9.1.7.0 (2.3.1) 2017-01-11 68056ae Java HotSpot(TM) 64-Bit Server VM 25.111-b14 on 1.8.0_111-b14 +jit [linux-x86_64] on Linux maruchan 4.9.0-11-generic #12-Ubuntu SMP Mon Dec 12 16:18:23 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux.

Expected Behavior

Example code:

class Dummy
  def initialize
    @payload = Array.new(100000)
  end

  def next
    @next = Dummy.new
  end
end

class Test
  def self.test
    dummy = Dummy.new
    iterations = 0

    while true
      dummy = dummy.next
      iterations += 1

      puts "ran iteration #{iterations}"

      GC.start if iterations % 10 == 0
      sleep if iterations == 200 && ENV['PAUSE_AFTER_ITERATIONS'] == '1'
    end
  end
end

Test.test

On MRI this code seems to behave correctly (e.g. it does not leak memory) and I can get up to hundreds of thousands of iterations with < 16MB memory being used.

Actual Behavior

Running with jruby:

$ jruby -J-Xmx200m leak_testcase.rb
ran iteration 1
ran iteration 2
...
ran iteration 466
ran iteration 467
Error: Your application used more memory than the safety cap of 200M.
Specify -J-Xmx####M to increase it (#### = cap size in MB).
Specify -w for full java.lang.OutOfMemoryError: Java heap space stack trace

By pausing after a few iterations and looking at a memory dump (with PAUSE_AFTER_ITERATIONS=1 jruby -J-Xmx200m leak_testcase.rb), we can see the following:

memory-dump-instances

E.g. all instances of Dummy are still alive, whereas looking at the code we are creating a linked list but we never keep references to previous nodes so we should only have a single instance visible in memory.

Looking at one of the instances, we see that they are being kept alive due to a reference stored on the stack:

references

and by asking for a list of stack references we see that there are two Dummy instances being referred to from the stack, not one as expected.

stack-references

It seems like the code generating is leaving the first dummy instance referenced on the stack and thus causing the memory leak as the whole list will be kept in memory, rather than just the last element.

We (@Talkdesk) hit this in production as we were iterating a large collection using hyperclient and thus were hitting memory limits even though we were doing it a slice at a time.

@headius

This comment has been minimized.

Show comment
Hide comment
@headius

headius Jan 13, 2017

Member

Thank you for the report!

Indeed, you're seeing a side effect of the way our compiler manages temporary variables. In this case, the first Dummy instance gets stored in one of these temp vars before being assigned to the dummy local variable. Subsequent assignments all assign to the dummy var rather than the temp var, so that first one remains rooted.

We're discussing ways to fix this.

Member

headius commented Jan 13, 2017

Thank you for the report!

Indeed, you're seeing a side effect of the way our compiler manages temporary variables. In this case, the first Dummy instance gets stored in one of these temp vars before being assigned to the dummy local variable. Subsequent assignments all assign to the dummy var rather than the temp var, so that first one remains rooted.

We're discussing ways to fix this.

@enebo

This comment has been minimized.

Show comment
Hide comment
@enebo

enebo Jan 16, 2017

Member

@subbuss and I realized that most of these trapped values in temp vars occurs as a result of a call. Since local variable assignments are handled as an operand we can add a little bit more smarts into our build and use the local variable as the result variable and get rid of this class of pinning an unwanted value.

With patch now in IR (before):

  6	%v_3 = search_const(scope<1> ;name: Dummy, no_priv: false)
  7	%v_4 = call_0o(%v_3 ;n:new, t:NO, cl:false)
  8	dummy(0:0) = copy(%v_4)

Now is (after):

  6	%v_3 = search_const(scope<1> ;name: Dummy, no_priv: false)
  7	dummy(0:0) = call_0o(%v_3 ;n:new, t:NO, cl:false)

Also of note this eliminated 3 instrs in the test case. This could translate into some small improvement in interpreter performance because it will reduce number of temp vars and number of instructions. It should not affect JIT performance at all because the JVM is good like that (except it MIGHT help bytecode sizes and thus make the JVM make new choices -- unlikely though).

My fix only changed some of builder to allow the lvar to be the rhs. I will break up some of the commits so I do not make some epic commit. This first commit fixes all calls and a few other instr which is a lion share of the cases.

Member

enebo commented Jan 16, 2017

@subbuss and I realized that most of these trapped values in temp vars occurs as a result of a call. Since local variable assignments are handled as an operand we can add a little bit more smarts into our build and use the local variable as the result variable and get rid of this class of pinning an unwanted value.

With patch now in IR (before):

  6	%v_3 = search_const(scope<1> ;name: Dummy, no_priv: false)
  7	%v_4 = call_0o(%v_3 ;n:new, t:NO, cl:false)
  8	dummy(0:0) = copy(%v_4)

Now is (after):

  6	%v_3 = search_const(scope<1> ;name: Dummy, no_priv: false)
  7	dummy(0:0) = call_0o(%v_3 ;n:new, t:NO, cl:false)

Also of note this eliminated 3 instrs in the test case. This could translate into some small improvement in interpreter performance because it will reduce number of temp vars and number of instructions. It should not affect JIT performance at all because the JVM is good like that (except it MIGHT help bytecode sizes and thus make the JVM make new choices -- unlikely though).

My fix only changed some of builder to allow the lvar to be the rhs. I will break up some of the commits so I do not make some epic commit. This first commit fixes all calls and a few other instr which is a lion share of the cases.

@enebo enebo added this to the JRuby 9.1.8.0 milestone Jan 16, 2017

@enebo enebo added the ir label Jan 16, 2017

@enebo enebo closed this in de714d0 Jan 16, 2017

@ivoanjo

This comment has been minimized.

Show comment
Hide comment
@ivoanjo

ivoanjo Jan 16, 2017

Contributor

Awesomely speedy fix, thanks! 👍

Contributor

ivoanjo commented Jan 16, 2017

Awesomely speedy fix, thanks! 👍

@brometeo

This comment has been minimized.

Show comment
Hide comment
@brometeo

brometeo Sep 26, 2017

Sorry for using this issue for solving my questions, but I see class names in visualvm and they are not what I get using that program for searching memory leaks in my applications. How can I see JRuby classes names in that form (rubyobj.Dummy)?

Thank you very much.

Sorry for using this issue for solving my questions, but I see class names in visualvm and they are not what I get using that program for searching memory leaks in my applications. How can I see JRuby classes names in that form (rubyobj.Dummy)?

Thank you very much.

@ivoanjo

This comment has been minimized.

Show comment
Hide comment
@ivoanjo

ivoanjo Sep 26, 2017

Contributor

@brometeo you need to start JRuby with -Xreify.classes=true, see https://engineering.talkdesk.com/ninjas-guide-to-getting-started-with-visualvm-f8bff061f7e7#5246 for more details.

Also you may hit #4643, see the ticket for a workaround.

Contributor

ivoanjo commented Sep 26, 2017

@brometeo you need to start JRuby with -Xreify.classes=true, see https://engineering.talkdesk.com/ninjas-guide-to-getting-started-with-visualvm-f8bff061f7e7#5246 for more details.

Also you may hit #4643, see the ticket for a workaround.

@brometeo

This comment has been minimized.

Show comment
Hide comment
@brometeo

brometeo Sep 26, 2017

Thank you very much.

Thank you very much.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment