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

Decreased performance between JRuby 1.7 and 9.1 #3973

Closed
dlhaines opened this issue Jun 17, 2016 · 12 comments
Closed

Decreased performance between JRuby 1.7 and 9.1 #3973

dlhaines opened this issue Jun 17, 2016 · 12 comments
Milestone

Comments

@dlhaines
Copy link

Apache Tomcat Version 7.0.69

jruby 9.1.0.0 (2.3.0) 2016-05-02 a633c63
Java HotSpot(TM) 64-Bit Server VM 25.91-b14 on 1.8.0_91-b14 +jit [linux-x86_64](Packaged by Warbler)

JVM settings are:
-XX:InitialHeapSize=2147483648 -XX:+ManagementServer -XX:MaxHeapSize=2147483648 -XX:MaxNewSize=536870912 -XX:NewSize=536870912 -XX:+PrintAdaptiveSizePolicy -XX:+PrintClassHistogram -XX:+PrintCommandLineFlags -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintStringDeduplicationStatistics -XX:+PrintTenuringDistribution -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC

We are using Sinatra as the framework.

Expected Behavior

Under JRuby 1.7.18 with about 748M of heap we get:

  • JVM is given around 700M of heap.
  • Predictable, consistant, response times for the application queries to external data sources. Response times are typically 3 to 7 seconds.
  • Typical sawtooth memory / GC pattern of frequent small collections with occasional larger collections. The only full GC is at startup.

Actual Behavior

Under JRuby 9.1.0.0 with 2G of heap we get:

  • Long response times for queries to the same data sources. Times more than double to greater than 14 seconds. Requests start getting timeouts.
  • GC collection behavior becomes erratic with mixed long and short collections. Many Full GC start happening, particularly as the run length
    increases. This happens with default GC settings and with G1.

Attached are PDF with graphs of the behavior.

After we stopped our test we got a 2G heap dump that shows a retained size of 1.3 G with about 1/2 of that retained by org.jruby.ext.openssl.X509Store. Off the top of my head that seems large. Any suggestions on how to look deeper at the dump would be welcome.

Application GC with JRuby 1.7
Dash Ramp 2.1-1.7.pdf

Application GC with JRuby 9.1
Dash Ramp 2.1-9.1.pdf

@estolfo
Copy link

estolfo commented Jun 17, 2016

Hi JRuby team,

I thought it might be mentioning that we've seen the Mongoid test suite execute much slower and use much more memory on JRuby-9.1 as well. Previously, on 9.0 it would complete in about 4 minutes:
https://travis-ci.org/mongodb/mongoid/jobs/120102531

On 1.7 it would take even less time:
https://travis-ci.org/mongodb/mongoid/jobs/106244439

and now it takes much longer before running out of memory:
https://travis-ci.org/mongodb/mongoid/jobs/138021305

I haven't spent much time debugging so please let me know if I can provide some more useful info.
Thanks!
Emily

@kares
Copy link
Member

kares commented Jun 17, 2016

@estolfo are you sure that relates to the reported issue (@dlhainer using mongoid)?
... if not please open a separate issue - just so we do not switch contexts eventually.

@kares
Copy link
Member

kares commented Jun 17, 2016

@dlhaines that sounds like the jruby-openssl leak we stumbled on recently please try an upgrade (0.9.17)
you'll find some relevant details on the mailing list (and the tracker): http://lists.ruby-lang.org/pipermail/jruby/2016-June/000434.html

@dlhaines
Copy link
Author

That does look like the issue. Are there instructions on how to do that kind of upgrade in the jruby environment?

@estolfo
Copy link

estolfo commented Jun 20, 2016

@kares Sure, I have to investigate some more in order to open a more specific issue but I thought it would be of interest to show an example of the vast difference in execution times between our test suite on 9.1 versus 9.0.
I'll open another issue when I have more details, thanks!

@enebo
Copy link
Member

enebo commented Jun 20, 2016

@dlhaines I think I told you how on irc last week but if not install jruby-openssl gem. It should not have this large memory footprint.

@enebo
Copy link
Member

enebo commented Jun 20, 2016

@estolfo Something else is amiss here since you run out of memory. I would be mildly surprised if anything is slower since 9.0 -> 9.1 since we made so many performance improvements. With that said, you issues is probably more about non-warmed up code which has had less done (although I would not expect it to be slower).

@enebo
Copy link
Member

enebo commented Jun 20, 2016

@estolfo although I do believe you. I was just mentioning that it was surprising to me.

@estolfo
Copy link

estolfo commented Jul 1, 2016

I agree that something is amiss. Our Travis CI builds show that performance is consistent on MRI: https://travis-ci.org/mongodb/mongoid/builds/140526206

From the stacktrace, it seems to run out of memory when the Ruby driver tries to create a new thread to monitor a server. If you have any ideas as to why this is happening, let me know!

@headius
Copy link
Member

headius commented Jul 11, 2016

@estolfo Looking at your travis logs, one of the first things that jumped out as me was OutOfMemoryError. When the JVM gets close to running out of memory, it spends exponentially more time running GC trying to dig itself out of a full heap. All of these suites fail eventually, and at least some of them seem to be hitting a memory limit.

It seems likely that you are hitting the same OpenSSL memory problem that @dlhaines claimed fixed his issue. You may want to try to set the mongoid runs on JRuby to install the most recent jruby-openssl gem before running. Hopefully that will fix it.

If not, I'd like you to open a new bug, since @dlhaines has confirmed his issue was fixed by updating jruby-openssl.

You might also try adding to JRUBY_OPTS env var the flag -J-Xmx###M where ### is something larger than the default 500MB limit we put on processes. Try "1000M" or "1G" and see if the run times improve. However, if we're using more than 500MB and shouldn't (or didn't before), that's still a bug.

@headius headius closed this as completed Jul 11, 2016
@headius headius added this to the Non-Release milestone Jul 11, 2016
@headius
Copy link
Member

headius commented Jul 11, 2016

Fixed by jruby/jruby-openssl#94.

@estolfo
Copy link

estolfo commented Jul 12, 2016

Thanks @headius! I'll do some testing today and update you.
I've opened #4012

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants