Forum: JRuby 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 Zelenkovas <lists@ruby-forum.com> 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 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 + 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}"

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.

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

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