Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Extra long IO.select with JRuby 9.1.15.0 #4971

Closed
HarlemSquirrel opened this issue Jan 12, 2018 · 5 comments
Closed

Extra long IO.select with JRuby 9.1.15.0 #4971

HarlemSquirrel opened this issue Jan 12, 2018 · 5 comments
Milestone
JRuby 9.1.17.0

Comments

@HarlemSquirrel
Copy link

I've noticed that certain pages use up all my Java heap space and never finish rendering.
Upon examinging with --profile enabled I noticed that JRuby 9.1.15.0 is spending much more time on IO.select than 9.1.14.0 does.

Java::JavaLang::OutOfMemoryError (Java heap space):
  
org.jruby.util.ByteList.ensure(ByteList.java:341)
org.jruby.util.io.EncodingUtils.strBufCat(EncodingUtils.java:1703)
org.jruby.util.io.EncodingUtils.strBufCat(EncodingUtils.java:1688)
org.jruby.util.io.EncodingUtils.encCrStrBufCat(EncodingUtils.java:1816)
org.jruby.util.io.EncodingUtils.encCrStrBufCat(EncodingUtils.java:1738)
org.jruby.RubyString.cat19(RubyString.java:1340)
org.jruby.RubyString.cat19(RubyString.java:1329)
org.jruby.RubyString.append19(RubyString.java:2240)
org.jruby.RubyString.concat19(RubyString.java:2268)
org.jruby.RubyString$INVOKER$i$1$0$concat19.call(RubyString$INVOKER$i$1$0$concat19.gen)
org.jruby.internal.runtime.methods.ProfilingDynamicMethod.call(ProfilingDynamicMethod.java:64)
org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:153)
org.jruby.runtime.callsite.ShiftLeftCallSite.call(ShiftLeftCallSite.java:24)
org.jruby.ir.interpreter.InterpreterEngine.processCall(InterpreterEngine.java:315)
org.jruby.ir.interpreter.InterpreterEngine.interpret(InterpreterEngine.java:159)
org.jruby.ir.interpreter.InterpreterEngine.interpret(InterpreterEngine.java:84)
org.jruby.internal.runtime.methods.InterpretedIRMethod.INTERPRET_METHOD(InterpretedIRMethod.java:182)
org.jruby.internal.runtime.methods.InterpretedIRMethod.call(InterpretedIRMethod.java:173)
org.jruby.internal.runtime.methods.ProfilingDynamicMethod.call(ProfilingDynamicMethod.java:64)
org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:153)
org.jruby.ir.interpreter.InterpreterEngine.processCall(InterpreterEngine.java:315)
org.jruby.ir.interpreter.StartupInterpreterEngine.interpret(StartupInterpreterEngine.java:74)
org.jruby.ir.interpreter.InterpreterEngine.interpret(InterpreterEngine.java:84)
org.jruby.internal.runtime.methods.InterpretedIRMethod.INTERPRET_METHOD(InterpretedIRMethod.java:186)
org.jruby.internal.runtime.methods.InterpretedIRMethod.call(InterpretedIRMethod.java:173)
org.jruby.internal.runtime.methods.ProfilingDynamicMethod.call(ProfilingDynamicMethod.java:64)
org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:153)
org.jruby.ir.interpreter.InterpreterEngine.processCall(InterpreterEngine.java:315)
org.jruby.ir.interpreter.InterpreterEngine.interpret(InterpreterEngine.java:159)
org.jruby.ir.interpreter.InterpreterEngine.interpret(InterpreterEngine.java:84)
org.jruby.internal.runtime.methods.InterpretedIRMethod.INTERPRET_METHOD(InterpretedIRMethod.java:182)
org.jruby.internal.runtime.methods.InterpretedIRMethod.call(InterpretedIRMethod.java:173)
127.0.0.1 - - [12/Jan/2018:16:15:47 EST] "GET /departments/53041446 HTTP/1.1" 500 0
- -> /departments/53041446
Total time: 47.93

Environment

JRUBY_OPTS='--dev -Xcompile.invokedynamic=true -J-XX:+UseCodeCacheFlushing -J-Xmx1g --profile'

Linux kem2028-Latitude-E7470 4.13.0-26-generic #29~16.04.2-Ubuntu SMP Tue Jan 9 22:00:44 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

openjdk version "1.8.0_151"
OpenJDK Runtime Environment (build 1.8.0_151-8u151-b12-0ubuntu0.16.04.2-b12)
OpenJDK 64-Bit Server VM (build 25.151-b12, mixed mode)-a`)

Other relevant info you may wish to add:

  • Installed or activated gems
  • Application/framework version (e.g. Rails, Sinatra)
  • Environment variables

Expected Behavior

Rails 5.1.4 + JRuby 9.1.14.0

Rendering view

Total time: 22.11

     total        self    children       calls  method
----------------------------------------------------------------
     21.92        0.02       21.90        9119  Kernel.require
     20.23        0.00       20.23           1  Rails::Command.invoke
     19.03        0.00       19.03         116  BasicObject#__send__
     18.99        0.00       18.99           1  Rails::Command::Base.perform
     18.99        0.00       18.99           1  Thor.dispatch
     18.99        0.00       18.98         254  Kernel.tap
     18.98        0.00       18.98           1  Thor::Invocation.invoke_command
     18.98        0.00       18.98           1  Thor::Command#run
     18.98        0.00       18.98           2  Rails::Command::ServerCommand#perform
     16.87        0.00       16.87           1  Rails::Server#start
     15.99        0.00       15.99           1  Rack::Server#start
     15.98        0.00       15.98           1  Rack::Handler::WEBrick.run
     15.95        0.00       15.95           1  WEBrick::GenericServer#start
     15.95        0.00       15.95           1  WEBrick::SimpleServer.start
     15.62       15.62        0.00          13  IO.select
      4.43        0.03        4.40        5991  Array#each
      1.66        0.09        1.57        9385  Class#new
      1.45        0.00        1.45           1  Bundler.require
      1.45        0.00        1.45           1  Bundler::Runtime#require
      1.23        0.00        1.23           1  Rails::Command.find_by_namespace
      1.23        0.00        1.23           1  Rails::Command::Behavior::ClassMethods.lookup
      1.08        0.09        1.00          48  Kernel.load
      0.88        0.02        0.86          47  Kernel.eval
      0.88        0.01        0.87         360  BasicObject#instance_eval
      0.84        0.00        0.84         138  Kernel.require
      0.84        0.00        0.84           9  TSort.tsort_each
      0.84        0.00        0.84           5  TSort.each_strongly_connected_component
      0.84        0.00        0.84         439  Method#call
      0.84        0.02        0.82         434  TSort.each_strongly_connected_component_from
      0.80        0.00        0.80           1  Rails::Server#log_to_stdout
      0.79        0.00        0.79           3  Rack::Server#wrapped_app
      0.79        0.00        0.79           1  Rails::Server#app
      0.79        0.00        0.79           1  Rack::Server#app
      0.79        0.00        0.79           1  Rack::Server#build_app_and_options_from_config
      0.79        0.00        0.79           1  Rack::Builder.parse_file
      0.79        0.00        0.79           1  Rack::Builder.new_from_string
      0.79        0.00        0.79           1  Rack::Builder#initialize
      0.79        0.00        0.79           1  Rails::Application#initialize!
      0.79        0.00        0.79           1  Rails::Initializable.run_initializers
      0.76        0.00        0.76           1  TSort.tsort_each
      0.73        0.00        0.73          97  Rails::Initializable::Initializer#run
      0.73        0.03        0.70         101  BasicObject#instance_exec
      0.73        0.00        0.73           2  Bundler.setup
      0.52        0.00        0.52         350  ActiveSupport::Dependencies::Loadable.load_dependency
      0.51        0.00        0.50       13234  Kernel.send
      0.44        0.01        0.44       11658  Proc#call
      0.40        0.40        0.00           1  Java::OrgJrubyExtOpenssl::OpenSSL.load
      0.38        0.01        0.38           2  Bundler.definition
      0.34        0.34        0.00           2  OpenSSL::PKey::DH#initialize
      0.34        0.00        0.34           1  Bundler::Runtime#setup

Actual Behavior

Rails 5.1.4 + JRuby 9.1.14.0

Rendering view

Total time: 53.85

     total        self    children       calls  method
----------------------------------------------------------------
     53.70        0.02       53.68        9085  Kernel.require
     52.27        0.00       52.27           1  Rails::Command.invoke
     50.98        0.00       50.98         116  BasicObject#__send__
     50.96        0.00       50.96           1  Rails::Command::Base.perform
     50.96        0.00       50.96           1  Thor.dispatch
     50.94        0.00       50.94         254  Kernel.tap
     50.94        0.00       50.94           1  Thor::Invocation.invoke_command
     50.94        0.00       50.94           1  Thor::Command#run
     50.94        0.00       50.94           2  Rails::Command::ServerCommand#perform
     49.26        0.00       49.26           1  Rails::Server#start
     48.49        0.00       48.49           1  Rack::Server#start
     48.49        0.00       48.49           1  Rack::Handler::WEBrick.run
     48.46        0.00       48.46           1  WEBrick::GenericServer#start
     48.46        0.00       48.46           1  WEBrick::SimpleServer.start
     37.57       37.57        0.00          25  IO.select
     14.53        0.03       14.50        5942  Array#each
     10.84       10.84        0.00           1  Thread#join
      1.31        0.00        1.31           1  Rails::Command.find_by_namespace
      1.31        0.00        1.31           1  Rails::Command::Behavior::ClassMethods.lookup
      1.17        0.00        1.17           1  Bundler.require
      1.17        0.00        1.17           1  Bundler::Runtime#require
      1.14        0.08        1.06        9674  Class#new
      0.78        0.78        0.00           1  Java::OrgJrubyExtOpenssl::OpenSSL.load
      0.77        0.01        0.76         360  BasicObject#instance_eval
      0.75        0.02        0.74          46  Kernel.eval
      0.74        0.07        0.67          48  Kernel.load
      0.71        0.00        0.71         140  Kernel.require
      0.71        0.00        0.71           9  TSort.tsort_each
      0.71        0.00        0.71           5  TSort.each_strongly_connected_component
      0.71        0.00        0.71         439  Method#call
      0.71        0.00        0.70         434  TSort.each_strongly_connected_component_from
      0.69        0.00        0.69           1  Rails::Server#log_to_stdout
      0.69        0.00        0.69           3  Rack::Server#wrapped_app
      0.69        0.00        0.69           1  Rails::Server#app
      0.69        0.00        0.69           1  Rack::Server#app
      0.69        0.00        0.69           1  Rack::Server#build_app_and_options_from_config
      0.69        0.00        0.69           1  Rack::Builder.parse_file
      0.69        0.00        0.68           1  Rack::Builder.new_from_string
      0.68        0.00        0.68           1  Rack::Builder#initialize
      0.68        0.00        0.68           1  Rails::Application#initialize!
      0.68        0.00        0.68           1  Rails::Initializable.run_initializers
      0.66        0.00        0.66           1  TSort.tsort_each
      0.62        0.00        0.62          97  Rails::Initializable::Initializer#run
      0.62        0.02        0.60         101  BasicObject#instance_exec
      0.54        0.00        0.54           2  Bundler.setup
      0.41        0.00        0.41         331  ActiveSupport::Dependencies::Loadable.load_dependency
      0.41        0.00        0.41       13235  Kernel.send
      0.35        0.00        0.34       11737  Proc#call
      0.30        0.00        0.30           1  Bundler::Runtime#setup
      0.27        0.00        0.27           1  Bundler::Runtime#requested_specs
@headius
Copy link
Member

headius commented Jan 25, 2018

Could you run your application with the --sample flag? That will turn on a lightweight JVM sampling profiler that will tell us more information.

IO.select is used for many IO operations, so this is not in itself an indication of a problem. Many threads will sit and wait for an incoming request in IO.select.

You may also stop by our IRC channel (#jruby on Freenode) or Gitter (jruby/jruby) and we can try to help you investigate performance issues.

@HarlemSquirrel
Copy link
Author

@headius Sorry for the late response, work has been quite busy.

Here's the output using the --sample flag.

jruby-9-1-15-rails-debug-20180207.txt

@headius
Copy link
Member

headius commented Feb 13, 2018

@HarlemSquirrel As far as I can see, it appears to be simply waiting in the lowest-levels of the select for something to happen.

There have been some improvements to select logic in JRuby 9.1.16 (due out this week, nightlies available). Could you retest? If it's still slow, we can look into bisecting changes during 9.1.15 to find the trigger, or dive a bit deeper.

If it's possible for you to make a sample repository that exhibits the problem it will make it easier for us to investigate as well.

@headius
Copy link
Member

headius commented Feb 13, 2018

9.1.16 nightly: https://projectodd.ci.cloudbees.com/job/jruby-stable-dist/lastSuccessfulBuild/artifact/release/

@HarlemSquirrel
Copy link
Author

Looks like this has gone away with 9.1.17.0.

Thanks guys!

@enebo enebo added this to the JRuby 9.1.17.0 milestone Apr 24, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
JRuby 9.1.17.0
Development

No branches or pull requests
3 participants
@headius @enebo @HarlemSquirrel