[jruby-user] Poor performance with JRuby on Rails

[Andre Zelenkovas]

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 to 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

--
Posted via http://www.ruby-forum.com/.

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

http://xircles.codehaus.org/manage_email

[Christian MICHON]

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...

--
Christian

[Benjamin Browning]

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

[Richie Vos]

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.

[Pradeep Singh]

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.

[Darshan Karandikar]

Suggest you to go through http://www.ruby-forum.com/topic/1119702 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 and enable config.threadsafe! in Rails. Gave
me the best performance and scalability.
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}"

[Andre Zelenkovas]

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.

[Joseph Athman]

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

[Andre Zelenkovas]

Hi Joseph

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