search

jruby / jruby

JRuby, an implementation of Ruby on the JVM
https://www.jruby.org
Other
3.8k stars 923 forks source link

Slowdown of pretty straight Rails app when switching to Java 8, enabling invokedynamic #1569

Closed donv closed 7 years ago

donv commented 10 years ago

The app is a pretty straight Rails app with scaffolding and accesses a PostgreSQL 9.3 database locally using ActiveRecord. Running on 64 bit Linux, Centos 6.5 with Oracle JDK 8 installed by RPM.

We start with these options:

jruby --2.0 --server -J-Xmx2G

Adding -Xcompile.invokedynamic=false makes performance about the same as Java 7, maybe a bit better.

The app uses the following Gemfile.lock:

GIT
  remote: https://github.com/DatekWireless/rails3-jquery-autocomplete.git
  revision: 5e20cd01ddb135c877b4edf482552c989196732d
  specs:
    rails3-jquery-autocomplete (1.0.12)
      rails (>= 3.0)

GEM
  remote: https://rubygems.org/
  remote: https://rails-assets.org/
  specs:
    actionmailer (3.2.16)
      actionpack (= 3.2.16)
      mail (~> 2.5.4)
    actionpack (3.2.16)
      activemodel (= 3.2.16)
      activesupport (= 3.2.16)
      builder (~> 3.0.0)
      erubis (~> 2.7.0)
      journey (~> 1.0.4)
      rack (~> 1.4.5)
      rack-cache (~> 1.2)
      rack-test (~> 0.6.1)
      sprockets (~> 2.2.1)
    activemodel (3.2.16)
      activesupport (= 3.2.16)
      builder (~> 3.0.0)
    activerecord (3.2.16)
      activemodel (= 3.2.16)
      activesupport (= 3.2.16)
      arel (~> 3.0.2)
      tzinfo (~> 0.3.29)
    activerecord-jdbc-adapter (1.3.6)
      activerecord (>= 2.2)
    activerecord-jdbcpostgresql-adapter (1.3.6)
      activerecord-jdbc-adapter (~> 1.3.6)
      jdbc-postgres (>= 9.1)
    activeresource (3.2.16)
      activemodel (= 3.2.16)
      activesupport (= 3.2.16)
    activesupport (3.2.16)
      i18n (~> 0.6, >= 0.6.4)
      multi_json (~> 1.0)
    ansi (1.4.3)
    arel (3.0.3)
    bcrypt-ruby (3.0.1-java)
    bootstrap-datepicker-rails (1.3.0.1)
      railties (>= 3.0)
    builder (3.0.4)
    capybara (2.2.1)
      mime-types (>= 1.16)
      nokogiri (>= 1.3.3)
      rack (>= 1.0.0)
      rack-test (>= 0.5.4)
      xpath (~> 2.0)
    childprocess (0.5.1)
      ffi (~> 1.0, >= 1.0.11)
    chunky_png (1.3.0)
    coffee-rails (3.2.2)
      coffee-script (>= 2.2.0)
      railties (~> 3.2.0)
    coffee-script (2.2.0)
      coffee-script-source
      execjs
    coffee-script-source (1.7.0)
    database_cleaner (1.2.0)
    docile (1.1.3)
    erubis (2.7.0)
    exception_notification (4.0.1)
      actionmailer (>= 3.0.4)
      activesupport (>= 3.0.4)
    execjs (2.0.2)
    ffi (1.9.3-java)
    hashie (2.0.5)
    hike (1.2.3)
    i18n (0.6.9)
    jdbc-postgres (9.3.1101)
    journey (1.0.4)
    jquery-rails (3.1.0)
      railties (>= 3.0, < 5.0)
      thor (>= 0.14, < 2.0)
    json (1.8.1-java)
    mail (2.5.4)
      mime-types (~> 1.16)
      treetop (~> 1.4.8)
    mime-types (1.25.1)
    mini_portile (0.5.2)
    minitest (4.7.5)
    minitest-reporters (0.14.24)
      ansi
      builder
      minitest (>= 2.12, < 5.0)
      powerbar
    monetize (0.1.4)
    money (6.0.1)
      i18n (~> 0.6.4)
      monetize (~> 0.1.3)
    money-rails (0.9.0)
      activesupport (>= 3.0)
      money (~> 6.0.0)
      railties (>= 3.0)
    multi_json (1.9.2)
    nokogiri (1.6.1-java)
      mini_portile (~> 0.5.0)
    paper_trail (3.0.1)
      activerecord (>= 3.0, < 5.0)
      activesupport (>= 3.0, < 5.0)
    polyglot (0.3.4)
    powerbar (1.0.11)
      ansi (~> 1.4.0)
      hashie (>= 1.1.0)
    puma (2.8.1-java)
      rack (>= 1.1, < 2.0)
    rack (1.4.5)
    rack-cache (1.2)
      rack (>= 0.4)
    rack-ssl (1.3.3)
      rack
    rack-test (0.6.2)
      rack (>= 1.0)
    rails (3.2.16)
      actionmailer (= 3.2.16)
      actionpack (= 3.2.16)
      activerecord (= 3.2.16)
      activeresource (= 3.2.16)
      activesupport (= 3.2.16)
      bundler (~> 1.0)
      railties (= 3.2.16)
    rails-assets-bootstrap (3.1.1)
      rails-assets-jquery (>= 1.9.0)
    rails-assets-jquery (1.11.0)
    rails-assets-jquery-ui (1.10.4)
      rails-assets-jquery (>= 1.6)
    railties (3.2.16)
      actionpack (= 3.2.16)
      activesupport (= 3.2.16)
      rack-ssl (~> 1.3.2)
      rake (>= 0.8.7)
      rdoc (~> 3.4)
      thor (>= 0.14.6, < 2.0)
    rake (10.1.1)
    rdoc (3.12.2)
      json (~> 1.4)
    rubyzip (1.1.2)
    rufus-scheduler (3.0.7)
      tzinfo
    sass (3.3.3)
    sass-rails (3.2.6)
      railties (~> 3.2.0)
      sass (>= 3.1.10)
      tilt (~> 1.3)
    schema_plus (1.4.1)
      rails (>= 3.2)
      valuable
    selenium-webdriver (2.40.0)
      childprocess (>= 0.5.0)
      multi_json (~> 1.0)
      rubyzip (~> 1.0)
      websocket (~> 1.0.4)
    simple_workflow (1.0.3)
      rails (>= 3.0.0)
    simplecov (0.8.2)
      docile (~> 1.1.0)
      multi_json
      simplecov-html (~> 0.8.0)
    simplecov-html (0.8.0)
    sprockets (2.2.2)
      hike (~> 1.2)
      multi_json (~> 1.0)
      rack (~> 1.0)
      tilt (~> 1.1, != 1.3.0)
    therubyrhino (2.0.3)
      therubyrhino_jar (>= 1.7.3)
    therubyrhino_jar (1.7.4)
    thor (0.18.1)
    tilt (1.4.1)
    timecop (0.7.1)
    treetop (1.4.15)
      polyglot
      polyglot (>= 0.3.1)
    turbo-sprockets-rails3 (0.3.11)
      railties (> 3.2.8, < 4.0.0)
      sprockets (>= 2.2.0)
    tzinfo (0.3.39)
    uglifier (2.5.0)
      execjs (>= 0.3.0)
      json (>= 1.8.0)
    unicode_utils (1.4.0)
    valuable (0.9.8)
    websocket (1.0.7)
    xpath (2.0.0)
      nokogiri (~> 1.3)

PLATFORMS
  java

DEPENDENCIES
  activerecord-jdbcpostgresql-adapter
  bcrypt-ruby (~> 3.0.1)
  bootstrap-datepicker-rails (~> 1.3.0.1)
  capybara
  chunky_png
  coffee-rails (~> 3.2.1)
  database_cleaner
  exception_notification
  jquery-rails
  minitest-reporters (< 1.0.0)
  money-rails
  nokogiri
  paper_trail
  puma
  rails (= 3.2.16)
  rails-assets-bootstrap
  rails-assets-jquery (< 2.0.0)
  rails-assets-jquery-ui
  rails3-jquery-autocomplete!
  rufus-scheduler
  sass-rails (~> 3.2.3)
  schema_plus
  selenium-webdriver
  simple_workflow
  simplecov
  therubyrhino
  timecop
  turbo-sprockets-rails3
  uglifier (>= 1.0.3)
  unicode_utils
headius commented 10 years ago

How much of a slowdown are we talking? And I assume you gave things ample time to warm up, yes?

The app is a pretty straight Rails app with scaffolding and accesses a PostgreSQL 9.3 database locally using ActiveRecord. Running on 64 bit Linux, Centos 6.5 with Oracle JDK 8 installed by RPM.

We start with these options:

jruby --2.0 --server -J-Xmx2G

Adding -Xcompile.invokedynamic=false makes performance about the same as Java 7, maybe a bit better.

The app uses the following Gemfile.lock:

GIT remote: https://github.com/DatekWireless/rails3-jquery-autocomplete.git revision: 5e20cd01ddb135c877b4edf482552c989196732d specs: rails3-jquery-autocomplete (1.0.12) rails (>= 3.0)

GEM remote: https://rubygems.org/ remote: https://rails-assets.org/ specs: actionmailer (3.2.16) actionpack (= 3.2.16) mail (~> 2.5.4) actionpack (3.2.16) activemodel (= 3.2.16) activesupport (= 3.2.16) builder (~> 3.0.0) erubis (~> 2.7.0) journey (~> 1.0.4) rack (~> 1.4.5) rack-cache (~> 1.2) rack-test (~> 0.6.1) sprockets (~> 2.2.1) activemodel (3.2.16) activesupport (= 3.2.16) builder (~> 3.0.0) activerecord (3.2.16) activemodel (= 3.2.16) activesupport (= 3.2.16) arel (~> 3.0.2) tzinfo (~> 0.3.29) activerecord-jdbc-adapter (1.3.6) activerecord (>= 2.2) activerecord-jdbcpostgresql-adapter (1.3.6) activerecord-jdbc-adapter (~> 1.3.6) jdbc-postgres (>= 9.1) activeresource (3.2.16) activemodel (= 3.2.16) activesupport (= 3.2.16) activesupport (3.2.16) i18n (~> 0.6, >= 0.6.4) multi_json (~> 1.0) ansi (1.4.3) arel (3.0.3) bcrypt-ruby (3.0.1-java) bootstrap-datepicker-rails (1.3.0.1) railties (>= 3.0) builder (3.0.4) capybara (2.2.1) mime-types (>= 1.16) nokogiri (>= 1.3.3) rack (>= 1.0.0) rack-test (>= 0.5.4) xpath (~> 2.0) childprocess (0.5.1) ffi (~> 1.0, >= 1.0.11) chunky_png (1.3.0) coffee-rails (3.2.2) coffee-script (>= 2.2.0) railties (~> 3.2.0) coffee-script (2.2.0) coffee-script-source execjs coffee-script-source (1.7.0) database_cleaner (1.2.0) docile (1.1.3) erubis (2.7.0) exception_notification (4.0.1) actionmailer (>= 3.0.4) activesupport (>= 3.0.4) execjs (2.0.2) ffi (1.9.3-java) hashie (2.0.5) hike (1.2.3) i18n (0.6.9) jdbc-postgres (9.3.1101) journey (1.0.4) jquery-rails (3.1.0) railties (>= 3.0, < 5.0) thor (>= 0.14, < 2.0) json (1.8.1-java) mail (2.5.4) mime-types (~> 1.16) treetop (~> 1.4.8) mime-types (1.25.1) mini_portile (0.5.2) minitest (4.7.5) minitest-reporters (0.14.24) ansi builder minitest (>= 2.12, < 5.0) powerbar monetize (0.1.4) money (6.0.1) i18n (~> 0.6.4) monetize (~> 0.1.3) money-rails (0.9.0) activesupport (>= 3.0) money (~> 6.0.0) railties (>= 3.0) multi_json (1.9.2) nokogiri (1.6.1-java) mini_portile (~> 0.5.0) paper_trail (3.0.1) activerecord (>= 3.0, < 5.0) activesupport (>= 3.0, < 5.0) polyglot (0.3.4) powerbar (1.0.11) ansi (~> 1.4.0) hashie (>= 1.1.0) puma (2.8.1-java) rack (>= 1.1, < 2.0) rack (1.4.5) rack-cache (1.2) rack (>= 0.4) rack-ssl (1.3.3) rack rack-test (0.6.2) rack (>= 1.0) rails (3.2.16) actionmailer (= 3.2.16) actionpack (= 3.2.16) activerecord (= 3.2.16) activeresource (= 3.2.16) activesupport (= 3.2.16) bundler (~> 1.0) railties (= 3.2.16) rails-assets-bootstrap (3.1.1) rails-assets-jquery (>= 1.9.0) rails-assets-jquery (1.11.0) rails-assets-jquery-ui (1.10.4) rails-assets-jquery (>= 1.6) railties (3.2.16) actionpack (= 3.2.16) activesupport (= 3.2.16) rack-ssl (~> 1.3.2) rake (>= 0.8.7) rdoc (~> 3.4) thor (>= 0.14.6, < 2.0) rake (10.1.1) rdoc (3.12.2) json (~> 1.4) rubyzip (1.1.2) rufus-scheduler (3.0.7) tzinfo sass (3.3.3) sass-rails (3.2.6) railties (~> 3.2.0) sass (>= 3.1.10) tilt (~> 1.3) schema_plus (1.4.1) rails (>= 3.2) valuable selenium-webdriver (2.40.0) childprocess (>= 0.5.0) multi_json (~> 1.0) rubyzip (~> 1.0) websocket (~> 1.0.4) simple_workflow (1.0.3) rails (>= 3.0.0) simplecov (0.8.2) docile (~> 1.1.0) multi_json simplecov-html (~> 0.8.0) simplecov-html (0.8.0) sprockets (2.2.2) hike (~> 1.2) multi_json (~> 1.0) rack (~> 1.0) tilt (~> 1.1, != 1.3.0) therubyrhino (2.0.3) therubyrhino_jar (>= 1.7.3) therubyrhino_jar (1.7.4) thor (0.18.1) tilt (1.4.1) timecop (0.7.1) treetop (1.4.15) polyglot polyglot (>= 0.3.1) turbo-sprockets-rails3 (0.3.11) railties (> 3.2.8, < 4.0.0) sprockets (>= 2.2.0) tzinfo (0.3.39) uglifier (2.5.0) execjs (>= 0.3.0) json (>= 1.8.0) unicode_utils (1.4.0) valuable (0.9.8) websocket (1.0.7) xpath (2.0.0) nokogiri (~> 1.3)

PLATFORMS java

DEPENDENCIES activerecord-jdbcpostgresql-adapter bcrypt-ruby (~> 3.0.1) bootstrap-datepicker-rails (~> 1.3.0.1) capybara chunky_png coffee-rails (~> 3.2.1) database_cleaner exception_notification jquery-rails minitest-reporters (< 1.0.0) money-rails nokogiri paper_trail puma rails (= 3.2.16) rails-assets-bootstrap rails-assets-jquery (< 2.0.0) rails-assets-jquery-ui rails3-jquery-autocomplete! rufus-scheduler sass-rails (~> 3.2.3) schema_plus selenium-webdriver simple_workflow simplecov therubyrhino timecop turbo-sprockets-rails3 uglifier (>= 1.0.3) unicode_utils

— Reply to this email directly or view it on GitHubhttps://github.com/jruby/jruby/issues/1569 .

donv commented 10 years ago

I gave it decent warm up, but it was so slow that testing was difficult. Without indy the hard requests give a throughput of 2 request per second for 10 concurrent users, while using indy makes requests time out after 60 seconds.

ansel1 commented 10 years ago

I'm also experiencing this. We're running a rails 3.2.17 in torquebox 3.1.0, jruby 1.7.11, java 8 oracle, ubuntu 12.04. We're getting may 10x worse performance just by flipping indy on and off. Not much indication why. It's not in gc, memory usage seems similar.

headius commented 10 years ago

These are interesting stories. They make me think there's a flaw in the indy subsystem in JRuby that I haven't hit through my testing and benchmarking.

Can you guys turn on -Xinvokedynamic.log.binding=true? I would expect things to settle down and you wouldn't see new binding after 50-100 requests. If we see that log continuing to burn along, it would mean that our indy logic is not giving up on some volatile call site. The cost of rebinding an indy call site is very high.

On Wed, Apr 23, 2014 at 5:03 PM, Russ Egan notifications@github.com wrote:

I'm also experiencing this. We're running a rails 3.2.17 in torquebox 3.1.0, jruby 1.7.11, java 8 oracle, ubuntu 12.04. We're getting may 10x worse performance just by flipping indy on and off. Not much indication why. It's not in gc, memory usage seems similar.

— Reply to this email directly or view it on GitHubhttps://github.com/jruby/jruby/issues/1569#issuecomment-41220624 .

kwando commented 10 years ago

Yeah, I have noticed this as well. Rails is pretty much unusable in development mode with invokedynamic enabled.

I made some graphs (very painful to do in Numbers btw).

Results obtained with siege (10 concurrent requests). siege http://localhost:3000/trivial_endpoint

I let it run for about 2800 request with indy and a few hundreds less without indy.

JRUBY_OPTS='-Xcompile.invokedynamic=false -J-Xmx1G' bin/rails s -e production JRUBY_OPTS='-Xcompile.invokedynamic=true -J-Xmx1G' bin/rails s -e production

ruby --version
jruby 1.7.12 (2.0.0p195) 2014-04-15 643e292 on Java HotSpot(TM) 64-Bit Server VM 1.8.0-b132 +indy [darwin-x86_64]

linear Blue line = +indy Green line = -indy

And with y=log(y) log Blue line = +indy Green line = -indy

With indy: max 12.6s, min: ~30ms Without indy: max 5.65s, min: ~10ms

I should probably have run this with only one concurrent request in siege...

$ JRUBY_OPTS='-Xcompile.invokedynamic=false -J-Xmx1G' bin/rails s -e production                                                                                                                                                       ✘
=> Booting Puma
=> Rails 4.1.0 application starting in production on http://0.0.0.0:3000
=> Run `rails server -h` for more startup options
=> Notice: server is listening on all interfaces (0.0.0.0). Consider using 127.0.0.1 (--binding option)
=> Ctrl-C to shutdown server
Puma 2.8.2 starting...
* Min threads: 0, max threads: 16
* Environment: production
* Listening on tcp://0.0.0.0:3000

The endpoint I'm hitting is pretty trival, two simple query to mongodb (mongoid).

ansel1 commented 10 years ago

So @headius, I've got invokedynamic.log.binding on...it's spewing logs constantly. You're thinking it should calm down at some point? how much time/load should I give it before expecting it to die down?

Another thought...we're using the new relic agent. Actually, we use both the java agent (for memory monitoring), and the ruby agent. I wonder if they are doing swizzling or reflection stuff which is borking up indy. I'll try removing them.

ansel1 commented 10 years ago

even without newrelic, still a lot of activity.

bbrowning commented 10 years ago

This issue was brought to my attention today and I thought I'd chime in a bit with what I've seen regarding indy performance and a very basic Rails4 application using a scaffolded 'posts' resource.

jruby 1.7.13 (1.9.3p392) 2014-06-24 43f133c on Java HotSpot(TM) 64-Bit Server VM 1.8.0-b132 +indy [linux-amd64]

Hitting http://localhost:8080/posts/1/edit with indy enabled: Total requests - throughput 25 requests - 2.49 req/s 50 requests - 1.83 req/s 75 requests - 1.17 req/s 100 requests - 7.54 req/s 125 requests - 52.96 req/s, indy log binding stops spewing output 200 requests - 60.30 req/s 400 requests - 66.26 req/s 800 requests - 70.82 req/s 1600 requests - 99.51 req/s 3000 requests - 134.25 req/s 5000 requests - 192.67 req/s 10000 requests - 274.61 req/s 15000 requests - 435.33 req/s 20000 requests - 740.95 req/s 25000 requests - 842.94 req/s 30000 requests - 844.24 req/s

So, after around 125 requests the indy log binding stopped spewing output and actually stopped all output, except for a tiny bit more around the 10,000 request mark. By 15,000 requests my very basic Rails 4 action was running around half its maximum throughput. By 25,000 requests it had achieved steady-state performance.

This is all hitting a single scaffolded edit action in a Rails4 controller. If I hit another action, like the scaffolded resource index (http://localhost:8080/posts/), it takes over 5,000 requests to get that other action to half maximum throughput and around 15,000 to get to maximum throughput.

For completeness sake, here are the numbers with indy disabled: Total requests - throughput 25 requests - 29.78 req/s 50 requests - 110.58 req/s 75 requests - 28.64 req/s 100 requests - 191.66 req/s 125 requests - 187.98 req/s 200 requests - 146.87 req/s 400 requests - 198.35 req/s 800 requests - 216.56 req/s 1600 requests - 278.24 req/s 3000 requests - 332.18 req/s 5000 requests - 376.23 req/s 10000 requests - 409.10 req/s 15000 requests - 478.43 req/s 20000 requests - 702.48 req/s 25000 requests - 777.38 req/s 30000 requests - 775.77 req/s

It appears with indy disabled things take about the same amount of time to reach maximum throughput (around 25,000 requests). However, the performance without indy surpasses the performance with indy until you get to the 20,000 request mark. Even after 5,000 requests indy is only at half the throughput of non-indy.

Again this is just a single controller action in a very basic Rails application. I'd speculate that for a lot of sites out there the time it takes for the entire application to run faster with invokedynamic enabled versus invokedynamic disabled is will be greater than the time the JVM actually stays up between deploys.

headius commented 8 years ago

I'd like to see this explored again on JRuby 9.1. I still suspect that something in Rails is causing us to keep rebinding indy call sites, which is very expensive.

mkoertgen commented 7 years ago

We also noticed severe performance degrades when migrating some rails apps.

They were deployed on docker images jruby:9.1.7-alpine and ran fine. Migrating to Rails 5 needed a jruby-update to at least 9.1.9. For the intrigued, here is why:

We directly switched to 9.1.12 where the performance dropped so bad that our app was basically impossible to use.

After a bit profiling we discovered that most of the time was spent in the cookie store.

Applying this SO answer solved the problem for us: After Upgrade To JRuby 9.1.9.0, Rails CookieStore Very Slow When Handling Encrypted Cookies (SO) which comes down to adding -J-Djava.security.egd=file:/dev/./urandom to your JRUBY_OPTS.

Here is some more explanation to this Avoiding JVM delays caused by random number generation

Hope this helps you guys.

headius commented 7 years ago

The original invokedynamic issue has almost certainly been fixed.

The additional mentions of entropy issues should be fixed with #4696 and #4857.