Poor performance with JRuby on Rails

Hello

I have a typical CRUD Ruby on Rails app with a fairly complex model and
the performance in JRuby is 6 times slower than MRI considering median
response times. I’m running 30 minute tests with a single-threaded
client to ensure runtimes are warmed up. I’ve tried both Webrick,
warbler on JBoss and Torquebox, to no avail. I’m reaching out to the
forum hoping for some tips.

Issue/fact summary:

JRuby-Rack seems to take up to 150ms just to dispatch the request into
the controller.

ActiveRecord activity is much slower on JRuby (by a factor of 10
sometimes.)

JSON generation is actually faster in JRuby than MRI.

Tried jruby.compile.mode=FORCE and jruby.frameless.mode = true.
Frameless mode seems to improve performance by about 5%.

YAML serialization is slower than JSON serialization in JRuby but the
same in MRI.

JRuby runtimes are using massive amounts of memory (up to 40 MB of
garbage per request.)

I’ve tested with a single runtime in JRuby with 2 GB max heap and 512 MB
max perm size.

Any tips are appreciated.

Thanks
Andre

1/ use trinidad (no need for warbler yet)
2/ share at least 1 controller code, related model and views if possible
3/ tell us more about your persistence layer, especially if it is SQL
without indexes…

On 9/5/12, Andre Z. [email protected] wrote:


Christian

Sounds like as a first step, which you may have already done to some
extent, you need to figure out exactly where the differences are. Have
you tried writing a simple script to exercise the relevant code paths of
the web requests outside of a web server? That would isolate any
differences between servers and compare raw JRuby vs MRI performance so
you’d know what needs tracking down from there. Break the web request
flow into manageable chunks and benchmark each chunk in isolation to see
narrow down the possible culprits and make it easier for others to
reproduce your results.

Ben

From my testing, one thing to look out for is the time between Rails
spent
overall on a request and the time Rails reports in the logs it worked on
the request can be quite different. Specifically, rails doesn’t account
for
time spent before the controller code runs (metals and so forth) as part
of
it’s response time.

We are using Tomcat, and when comparing the response times Rails said to
what Tomcat said, we saw drastically different numbers. I recommend
sticking a metal at the top of your middleware stack to get more
accurate
numbers. Something like:

app/metals/request_timer.rb

class RequestTimer
def initialize(app)
@app = app
end

def call(env)
begin
rack_response = nil
response_time = Benchmark.ms do
rack_response = @app.call(env)
end
rack_response
ensure
Rails.logger.info(“Request actually took:
#{response_time.to_i}ms”)
# ActionController::Dispatcher usually does this, but we’re
outside
of its
# control here
Rails.logger.flush if Rails.logger.respond_to?(:flush)
end
end
end

config/application.rb

module YourApplication
class Application < Rails::Application
#…
config.middleware.insert(0, “RequestTimer”)
end
end

You can then move this middleware up and down the stack to find where
time’s being lost (change the insert location). This may help track down
the JRuby-Rack missing time.

You said you’re only doing 1 request at a time, but if you’re not, watch
out for your config/database.yml’s pool_size and wait_timeout settings.
Those can drastically affect your performance if you’re using threaded
requests (eg config.threadsafe! and a threaded app server). This may
help
track down the extra ActiveRecord time.

Does your massive amounts of memory usage stabilize over time? And what
type of garbage/memory (PermGen?). Might be worth hooking up something
like
JConsole to track that one down.

Suggest you to go through JRuby on Rails experience - JRuby - Ruby-Forum where
I have shared my experience with JRoR. I also had faced performance
issues in the beginning. Summarizing the configs that solved the
problems for me:

  1. Write thread-safe code + enable config.threadsafe! in Rails + set
    jruby.min and max runtimes = 1. This config. gave me the best CPU and
    memory utilization of all configs.
  2. Increase the AR conn. pool wait timeout.
  3. Warm up AR conn. pool by either using AR-JDBC bridge OR following
    custom script (helps prevent the overhead of creating db conns at
    runtime which was one bottleneck in my case):

#db pool warmup

puts “db pool warmup starting… #{Time.now}”
warm_up_count = APP_CONSTANTS[‘dbconn_warm_up_count’].to_i
conn_array = Array.new
for i in 1…warm_up_count do
conn_array[i] = ActiveRecord::Base.connection_pool.checkout
puts ‘chekedout ‘+i.to_s+’…’
end

puts ‘warmed up…==============…’
for i in 1…warm_up_count do
ActiveRecord::Base.connection_pool.checkin(conn_array[i])
puts ‘chekedin ‘+i.to_s+’…’
end
puts “db pool warmup done… #{Time.now}”

Hi all

Thanks for the suggestions, I really appreciate them. I’ll try them as
soon as I’m able and I’ll post back results.

Andre

Put this code in a new file (I called mine middleware.rb) in
initializers
directory and have a look at the results. Adjust according to your
middleware list by checking out ‘rake middleware’ -

timing_method = %q{
alias_method :old_call, :call
def call(env)
time1 = Time.now
ret_value = old_call(env)
puts “time taken at #{self.class} => #{Time.now - time1}”
ret_value
end
}

Rack::Lock.class_eval(timing_method)
ActiveSupport::Cache::Strategy::LocalCache::Middleware.class_eval(timing_method)
Rack::Runtime.class_eval(timing_method)
Rack::MethodOverride.class_eval(timing_method)
ActionDispatch::RequestId.class_eval(timing_method)
Rails::Rack::Logger.class_eval(timing_method)
ActionDispatch::ShowExceptions.class_eval(timing_method)
ActionDispatch::DebugExceptions.class_eval(timing_method)
ActionDispatch::RemoteIp.class_eval(timing_method)
ActionDispatch::Reloader.class_eval(timing_method)
ActionDispatch::Callbacks.class_eval(timing_method)
ActiveRecord::ConnectionAdapters::ConnectionManagement.class_eval(timing_method)
ActiveRecord::QueryCache.class_eval(timing_method)
ActionDispatch::Cookies.class_eval(timing_method)
ActiveRecord::SessionStore.class_eval(timing_method)
ActionDispatch::Flash.class_eval(timing_method)
ActionDispatch::ParamsParser.class_eval(timing_method)
ActionDispatch::Head.class_eval(timing_method)
Rack::ConditionalGet.class_eval(timing_method)
Rack::ETag.class_eval(timing_method)
ActionDispatch::BestStandardsSupport.class_eval(timing_method)
#RailsWarden::Manager.class_eval(timing_method)
App::Application.routes.class_eval(timing_method)

Also, may I request you to try one test with the gem ‘webricknio’ (run
server with ‘rails s wnio’)?

In my tests I’ve seen about 1MB increase in heap per request which I
already consider quite excessive.

Is this in Development mode or Production mode? Someone can correct me
if
I’m wrong, but since Rails reloads classes in Development mode by
default
you might not be allowing JRuby to JIT code enough since each request is
reloading a lot of classes.

What versions of JRuby, Java, and Rails are you using? Also what DB and
ActiveRecord JDBC driver are you using?

Joe

Hi Joseph

Production mode.
JRuby 1.6.7
Java 1.6.0_33
Ruby 1.9.3-p194
mysql_connector_java_5_1_13

Thanks
Andre