Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

OutOfMemoryError with 9.1.3.0 #4127

Closed
MartinKoerner opened this issue Sep 1, 2016 · 17 comments
Closed

OutOfMemoryError with 9.1.3.0 #4127

MartinKoerner opened this issue Sep 1, 2016 · 17 comments

Comments

@MartinKoerner
Copy link

Environment

Provide at least:

  • jruby 9.1.3.0 (2.3.1) 2016-08-29 a2a3b29 Java HotSpot(TM) 64-Bit Server VM 25.20-b23 on 1.8.0_20-b26 +jit [darwin-x86_64]
  • JRUBY_OPTS='--debug --dev -Xcompile.invokedynamic=false -J-XX:TieredStopAtLevel=1 -J-XX:+CICompilerCountPerCPU -Xjit.threshold=500 -J-XX:+TieredCompilation -J-XX:+UseG1GC -J-XX:ReservedCodeCacheSize=256m -J-Xss2048k -J-Xms2048m -J-Xmx2048m'
  • uname -a: 15.6.0 Darwin Kernel Version 15.6.0: Thu Jun 23 18:25:34 PDT 2016; root:xnu-3248.60.10~1/RELEASE_X86_64 x86_64
  • Rails 4.2.

Expected Behavior

  • Command "bin/rails g our/generator" should run without problems
  • The generator itself is resource-intensive, but ran always without problems in JRuby 1.7.x, 9.0.4.0, 9.0.5.0 and 9.1.2.0

Actual Behavior

Generator runs for a while, than he hangs on one file (it is the same file every time, but it is not very special in the generated output) and after some time prints:

LoadError: load error: rails/commands/generate -- java.lang.OutOfMemoryError: Java heap space
              require at org/jruby/RubyKernel.java:955
     block in require at /usr/local/var/rbenv/versions/jruby-9.1.3.0/lib/ruby/gems/shared/gems/activesupport-4.2.7.1/lib/active_support/dependencies.rb:274
      load_dependency at /usr/local/var/rbenv/versions/jruby-9.1.3.0/lib/ruby/gems/shared/gems/activesupport-4.2.7.1/lib/active_support/dependencies.rb:240
              require at /usr/local/var/rbenv/versions/jruby-9.1.3.0/lib/ruby/gems/shared/gems/activesupport-4.2.7.1/lib/active_support/dependencies.rb:274
     require_command! at /usr/local/var/rbenv/versions/jruby-9.1.3.0/lib/ruby/gems/shared/gems/railties-4.2.7.1/lib/rails/commands/commands_tasks.rb:123
  generate_or_destroy at /usr/local/var/rbenv/versions/jruby-9.1.3.0/lib/ruby/gems/shared/gems/railties-4.2.7.1/lib/rails/commands/commands_tasks.rb:130
             generate at /usr/local/var/rbenv/versions/jruby-9.1.3.0/lib/ruby/gems/shared/gems/railties-4.2.7.1/lib/rails/commands/commands_tasks.rb:50
         run_command! at /usr/local/var/rbenv/versions/jruby-9.1.3.0/lib/ruby/gems/shared/gems/railties-4.2.7.1/lib/rails/commands/commands_tasks.rb:39
                at /usr/local/var/rbenv/versions/jruby-9.1.3.0/lib/ruby/gems/shared/gems/railties-4.2.7.1/lib/rails/commands.rb:17
              require at org/jruby/RubyKernel.java:955
                at bin/rails:1

It will try to get a memory dump...

@enebo enebo added this to the JRuby 9.1.4.0 milestone Sep 1, 2016
@MartinKoerner
Copy link
Author

Looks like it has something to do with internal String handling. I took a heap dump both with 9.1.2.0 shortly after the problematic file and with 9.1.3.0 shortly before the OOM Exception:

9.1.2.0: 194.000 Strings have 194.000 char[] with 15 MB:
9 1 2 0

9.1.3.0: 196.000 Strings have 196.000 char[] with 220 MB:
9 1 3 0

I took a screenshot of one example char[] list, but I guess it's not very useful. If I should send you the heap dump I need a location:

9 1 3 0_char

@headius
Copy link
Member

headius commented Sep 1, 2016

The heap dump would be helpful. It's not clear what those strings are from, but I'd need to look at who is holding a reference to them. My first thought would be something changed in our Java integration that's holding too many string keys now, but I don't think we ever cached anything using Java bytecode signatures like (Ljava/util/function/Consumer....

@headius
Copy link
Member

headius commented Sep 1, 2016

Oh and as far as sending the heap dump...

Easiest is probably to zip it up and post it on Dropbox or Google Drive or something and share a link with us. Time is of the essence...we'd like to investigate this and spin a 9.1.4.0 release ASAP.

@MartinKoerner
Copy link
Author

You have a link in your inbox.

@kares
Copy link
Member

kares commented Sep 1, 2016

so far ... I see 2 StringBuilder instances (locals) holding up to 500MB the bigger is 400MB starts with content such as: #<Objectfab::CisGen::Dsl::Model:0x5b22f3ac @name="Freigabe", @presenters={"pr_freigabe_info"=>#<Objectfab::CisGen::Dsl::Presenter:0x671d1b4d @create=#<Objectfab::CisGen::Dsl::Action:0x5ca92647 @names={}, @is_user_generated=true, @parent ...
... so it seems to me like were chasing an application specific leak for you.
are you sure the setup is the very same with 9.1.2 ?

@MartinKoerner
Copy link
Author

As I wrote, the generator itself is very resource-intense, yes.

But I ran it today several times with 9.0.5.0 and 9.1.3.0 in the same project. The only 2 things I changed were the "ruby"-line in the Gemfile and the "rbenv shell" command

@headius
Copy link
Member

headius commented Sep 1, 2016

@MartinKoerner Can you get us a dump of the same app under 9.1.2.0? It would allow us to diff the two and see what changed to consume more memory.

@headius
Copy link
Member

headius commented Sep 1, 2016

@MartinKoerner Ok, a couple things, now that I'm looking at your largest heap dump.

I see what @kares sees...the largest object in the system is a char[] containing what looks like inspect output from one of your model objects. However I don't think this is necessarily an application issue. For example, a NameError raised from a large object graph will in some cases end up inspecting that graph and holding on to a giant string.

What I can't tell is where this StringBuilder came from or what it's being used for. In the largest dump, it appears to be in a JVM local variable, and I can't see what the code using that variable is doing.

A couple suggestions and questions:

  • Are you sure the app uses more memory? Check process size for both. I'm wondering if our default heap cap logic is screwed up in some way on 9.1.3.0.
  • If you determine that the app really is using more memory, figure out how much more you need to give it to run (using -Xmx####M or -J-Xmx####M to set max heap in MB). If no amount of memory works, we have a leak. If you can get it to work reasonably with a larger heap, we may just have something that got bigger (maybe in error).
  • Try running without did_you_mean by passing --disable-did_you_mean to JRuby. This decorates NameError with additional logic, and it's possible that's retaining something it shouldn't.

I will keep poking around the dump I have and try to find more clues.

@headius
Copy link
Member

headius commented Sep 1, 2016

It looks like the big StringBuilder is in response to a Ruby call to inspect some object graph that has a singleton Objectfab::CisGen::Dsl::Model object. Is it expected in your app that inspecting one of these models would produce a 400MB string?

@headius
Copy link
Member

headius commented Sep 1, 2016

The top-level object that triggers the inspect appears to be a ObjectFab::CisGen::Dsl::Presenter, FWIW.

@headius
Copy link
Member

headius commented Sep 1, 2016

Here's a patch that would reduce the memory needed for inspect by going with ByteList right away: https://gist.github.com/headius/59e19a3a4a45c63b06cc9876a8148e28

This isn't a fix but it would help this large inspect fit in memory.

@headius
Copy link
Member

headius commented Sep 1, 2016

Since we need to put out 9.1.4.0 for a couple other regressions in 9.1.3.0, we're probably going to have to punt this to 9.1.5.0 and work with you to figure it out.

headius added a commit to headius/jruby that referenced this issue Sep 1, 2016
This should reduce the overhead of inspecting by avoiding the
intermediate StringBuilder/char[] and subsequent conversion to
byte[]. There are a few extra objects created along the way
(java.lang.String.getBytes, RubyString for class name, etc) but
overall memory use should reduce around 3x: a US-ASCII
string would need 2x byte size in the StringBuilder, and the
builder is still alive when we create the eventual byte[] for a
total of 3x max memory use during inspect.

Relates to jruby#4127, but does not constitute a fix for memory issues
there.
@enebo enebo modified the milestones: JRuby 9.1.4.0, JRuby 9.1.5.0 Sep 1, 2016
@MartinKoerner
Copy link
Author

MartinKoerner commented Sep 2, 2016

  • disabling --disable-did_you_mean did not change anything
  • changing Memory usage to "-J-Xms8g -J-Xmx8g" made the waiting time longer but in the end did noch change anything
  • the codebase is somewhat old and "inspect" was indeed causing troubles for debugging outputs sometime. But it isn't used for the normal behavior
    • I took all ObjectFab::DSL classes and gave them a simple def inspect; "#{self.class}#{object_id}"; end
    • So I got the real exception:
NoMethodError: protected method `destination=' called for #
Did you mean?  destination
           initialize at /usr/local/var/rbenv/versions/jruby-9.1.3.0/lib/ruby/gems/shared/gems/thor-0.19.1/lib/thor/actions/empty_directory.rb:36
           initialize at /usr/local/var/rbenv/versions/jruby-9.1.3.0/lib/ruby/gems/shared/gems/thor-0.19.1/lib/thor/actions/create_file.rb:37
          create_file at /usr/local/var/rbenv/versions/jruby-9.1.3.0/lib/ruby/gems/shared/gems/thor-0.19.1/lib/thor/actions/create_file.rb:25
             template at /Users/martin/RubymineProjects/cis/lib/generators/objectfab/lib/merged_markers/marker_merge.rb:49

So it looks like a Thor exception, but - I'm using the same Thor 0.19.1 with the other JRuby versions (I double checked the code) - and the method destination= is there! It's a protected level method though...

@MartinKoerner
Copy link
Author

MartinKoerner commented Sep 2, 2016

So is it related with this bug? #2198

@MartinKoerner
Copy link
Author

MartinKoerner commented Sep 2, 2016

I sent you the heap for the 9.1.2.0 run in case you still find it helpful.

Unfortunately, I won't be able to investigate further until next Tuesday...

@MartinKoerner
Copy link
Author

So, I got a little bit further:

  1. The memory issue comes from a circular dependence in the inspecting code. Sorry, that I bothered you with that.
  2. I still don't know, why the inspecting is started while printing the "NoMethodError", even if did_you_mean is disabled
  3. The Exception is only thrown, if the "--dev" flag is active. If I remove it, the generator runs correctly. All other starting-related flags seem to be no problem

@headius should I open new tickets for 2 and 3? Or simply rename this one (the OOM is not the problem anymore)

@headius
Copy link
Member

headius commented Sep 6, 2016

@MartinKoerner Definitely file one or two new issues depending on how you feel about the other items. Our process is that bugs like this one get closed as "Invalid" so we don't get confusing context.

headius added a commit to headius/jruby that referenced this issue Sep 30, 2016
This should reduce the overhead of inspecting by avoiding the
intermediate StringBuilder/char[] and subsequent conversion to
byte[]. There are a few extra objects created along the way
(java.lang.String.getBytes, RubyString for class name, etc) but
overall memory use should reduce around 3x: a US-ASCII
string would need 2x byte size in the StringBuilder, and the
builder is still alive when we create the eventual byte[] for a
total of 3x max memory use during inspect.

Relates to jruby#4127, but does not constitute a fix for memory issues
there.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

4 participants