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

[donv]

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]

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

• Charlie (mobile)
  On Mar 20, 2014 6:33 PM, "Uwe Kubosch" notifications@github.com wrote:

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//issues/1569
.

[donv]

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]

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]

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.

• Charlie

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//issues/1569#issuecomment-41220624
.

[kwando]

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]

Blue line = +indy
Green line = -indy

And with y=log(y)

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]

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]

even without newrelic, still a lot of activity.

[bbrowning]

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]

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]

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:

• active_support/core_ext/marshal breaking jRuby Marshal #28342
• Marshal.load fails with an explicit nil proc #4526).

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]

The original invokedynamic issue has almost certainly been fixed.

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