undefined method on high load #22

Closed
carlhoerberg opened this Issue Mar 31, 2012 · 5 comments

Projects

None yet

3 participants

@carlhoerberg

i've done some benchmarks against different app servers, and i notice that Mizuno (unlike any other app server i've tested) starts to throw undefined method exceptions on either high load (100 connections for ~40 sec) with few threads (--threads 20) or almost immediately on many threads and 100 concurrent connections.

this is the app used: https://github.com/carlhoerberg/heroku-jruby-example/tree/mizuno

this is the load test:

$ siege -b -c 100 -t 60S http://jruby-mizuno.herokuapp.com/

this is the error thrown:

ActionView::Template::Error (undefined method `_app_views_hello_index_html_erb___559472807_4716' for #<#<Class:0x40ba3671>:0x14e6103c>):
  org/jruby/RubyBasicObject.java:1710:in `__send__'
  org/jruby/RubyKernel.java:2105:in `send'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_view/template.rb:143:in `render'
  vendor/bundle/jruby/1.9/gems/activesupport-3.2.3/lib/active_support/notifications.rb:125:in `instrument'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_view/template.rb:141:in `render'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_view/renderer/template_renderer.rb:47:in `render_template'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_view/renderer/abstract_renderer.rb:38:in `instrument'
  vendor/bundle/jruby/1.9/gems/activesupport-3.2.3/lib/active_support/notifications.rb:123:in `instrument'
  vendor/bundle/jruby/1.9/gems/activesupport-3.2.3/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
  vendor/bundle/jruby/1.9/gems/activesupport-3.2.3/lib/active_support/notifications/instrumenter.rb:19:in `instrument'
  vendor/bundle/jruby/1.9/gems/activesupport-3.2.3/lib/active_support/notifications.rb:123:in `instrument'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_view/renderer/abstract_renderer.rb:38:in `instrument'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_view/renderer/template_renderer.rb:46:in `render_template'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_view/renderer/template_renderer.rb:54:in `render_with_layout'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_view/renderer/template_renderer.rb:45:in `render_template'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_view/renderer/template_renderer.rb:18:in `render'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_view/renderer/renderer.rb:36:in `render_template'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_view/renderer/renderer.rb:17:in `render'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/abstract_controller/rendering.rb:110:in `_render_template'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_controller/metal/streaming.rb:225:in `_render_template'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/abstract_controller/rendering.rb:103:in `render_to_body'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_controller/metal/renderers.rb:28:in `render_to_body'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_controller/metal/compatibility.rb:50:in `render_to_body'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/abstract_controller/rendering.rb:88:in `render'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_controller/metal/rendering.rb:16:in `render'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_controller/metal/instrumentation.rb:40:in `render'
  vendor/bundle/jruby/1.9/gems/activesupport-3.2.3/lib/active_support/core_ext/benchmark.rb:5:in `ms'
  jruby/lib/ruby/1.9/benchmark.rb:310:in `

  vendor/bundle/jruby/1.9/gems/activesupport-3.2.3/lib/active_support/core_ext/benchmark.rb:5:in `ms'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_controller/metal/instrumentation.rb:40:in `render'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_controller/metal/instrumentation.rb:83:in `cleanup_view_runtime'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_controller/metal/instrumentation.rb:39:in `render'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_controller/metal/implicit_render.rb:10:in `default_render'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_controller/metal/implicit_render.rb:5:in `send_action'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/abstract_controller/base.rb:167:in `process_action'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_controller/metal/rendering.rb:10:in `process_action'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/abstract_controller/callbacks.rb:18:in `process_action'
  vendor/bundle/jruby/1.9/gems/activesupport-3.2.3/lib/active_support/callbacks.rb:406:in `_run__1066175785__process_action__1729319655__callbacks'
  org/jruby/RubyBasicObject.java:1698:in `__send__'
  org/jruby/RubyKernel.java:2097:in `send'
  vendor/bundle/jruby/1.9/gems/activesupport-3.2.3/lib/active_support/callbacks.rb:405:in `__run_callback'
  vendor/bundle/jruby/1.9/gems/activesupport-3.2.3/lib/active_support/callbacks.rb:390:in `_run_process_action_callbacks'
  org/jruby/RubyBasicObject.java:1704:in `__send__'
  org/jruby/RubyKernel.java:2101:in `send'
  vendor/bundle/jruby/1.9/gems/activesupport-3.2.3/lib/active_support/callbacks.rb:81:in `run_callbacks'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/abstract_controller/callbacks.rb:17:in `process_action'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_controller/metal/rescue.rb:29:in `process_action'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
  vendor/bundle/jruby/1.9/gems/activesupport-3.2.3/lib/active_support/notifications.rb:123:in `instrument'
  vendor/bundle/jruby/1.9/gems/activesupport-3.2.3/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
  vendor/bundle/jruby/1.9/gems/activesupport-3.2.3/lib/active_support/notifications/instrumenter.rb:19:in `instrument'
  vendor/bundle/jruby/1.9/gems/activesupport-3.2.3/lib/active_support/notifications.rb:123:in `instrument'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_controller/metal/instrumentation.rb:29:in `process_action'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_controller/metal/params_wrapper.rb:205:in `process_action'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/abstract_controller/base.rb:121:in `process'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/abstract_controller/rendering.rb:45:in `process'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_controller/metal.rb:203:in `dispatch'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_controller/metal/rack_delegation.rb:14:in `dispatch'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_controller/metal.rb:246:in `action'
  org/jruby/RubyProc.java:258:in `call'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_dispatch/routing/route_set.rb:73:in `dispatch'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_dispatch/routing/route_set.rb:36:in `call'
  vendor/bundle/jruby/1.9/gems/journey-1.0.3/lib/journey/router.rb:68:in `call'
  org/jruby/RubyArray.java:1615:in `each'
  vendor/bundle/jruby/1.9/gems/journey-1.0.3/lib/journey/router.rb:56:in `call'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_dispatch/routing/route_set.rb:600:in `call'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_dispatch/middleware/best_standards_support.rb:17:in `call'
  vendor/bundle/jruby/1.9/gems/rack-1.4.1/lib/rack/etag.rb:23:in `call'
  vendor/bundle/jruby/1.9/gems/rack-1.4.1/lib/rack/conditionalget.rb:25:in `call'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_dispatch/middleware/head.rb:14:in `call'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_dispatch/middleware/params_parser.rb:21:in `call'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_dispatch/middleware/flash.rb:242:in `call'
  vendor/bundle/jruby/1.9/gems/rack-1.4.1/lib/rack/session/abstract/id.rb:205:in `context'
  vendor/bundle/jruby/1.9/gems/rack-1.4.1/lib/rack/session/abstract/id.rb:200:in `call'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_dispatch/middleware/cookies.rb:338:in `call'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_dispatch/middleware/callbacks.rb:28:in `call'
  vendor/bundle/jruby/1.9/gems/activesupport-3.2.3/lib/active_support/callbacks.rb:408:in `_run__1642029382__call__1355252540__callbacks'
  org/jruby/RubyBasicObject.java:1698:in `__send__'
  org/jruby/RubyKernel.java:2097:in `send'
  vendor/bundle/jruby/1.9/gems/activesupport-3.2.3/lib/active_support/callbacks.rb:405:in `__run_callback'
  vendor/bundle/jruby/1.9/gems/activesupport-3.2.3/lib/active_support/callbacks.rb:390:in `_run_call_callbacks'
  org/jruby/RubyBasicObject.java:1698:in `__send__'
  org/jruby/RubyKernel.java:2097:in `send'
  vendor/bundle/jruby/1.9/gems/activesupport-3.2.3/lib/active_support/callbacks.rb:81:in `run_callbacks'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_dispatch/middleware/remote_ip.rb:31:in `call'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_dispatch/middleware/debug_exceptions.rb:16:in `call'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_dispatch/middleware/show_exceptions.rb:56:in `call'
  vendor/bundle/jruby/1.9/gems/railties-3.2.3/lib/rails/rack/logger.rb:26:in `call_app'
  vendor/bundle/jruby/1.9/gems/railties-3.2.3/lib/rails/rack/logger.rb:16:in `call'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_dispatch/middleware/request_id.rb:22:in `call'
  vendor/bundle/jruby/1.9/gems/rack-1.4.1/lib/rack/methodoverride.rb:21:in `call'
  vendor/bundle/jruby/1.9/gems/rack-1.4.1/lib/rack/runtime.rb:17:in `call'
  vendor/bundle/jruby/1.9/gems/activesupport-3.2.3/lib/active_support/cache/strategy/local_cache.rb:72:in `call'
  vendor/bundle/jruby/1.9/gems/actionpack-3.2.3/lib/action_dispatch/middleware/static.rb:62:in `call'
  vendor/bundle/jruby/1.9/gems/railties-3.2.3/lib/rails/engine.rb:479:in `call'
  vendor/bundle/jruby/1.9/gems/railties-3.2.3/lib/rails/application.rb:220:in `call'
  org/jruby/RubyBasicObject.java:1704:in `__send__'
  org/jruby/RubyKernel.java:2101:in `send'
  vendor/bundle/jruby/1.9/gems/railties-3.2.3/lib/rails/railtie/configurable.rb:30:in `method_missing'
  vendor/bundle/jruby/1.9/gems/mizuno-0.5.1/lib/mizuno/rack_servlet.rb:75:in `service'
  org/jruby/RubyKernel.java:1197:in `catch'
  vendor/bundle/jruby/1.9/gems/mizuno-0.5.1/lib/mizuno/rack_servlet.rb:74:in `service'
  vendor/bundle/jruby/1.9/gems/mizuno-0.5.1/lib/mizuno/rack_servlet.rb:236:in `handle_exceptions'
  vendor/bundle/jruby/1.9/gems/mizuno-0.5.1/lib/mizuno/rack_servlet.rb:45:in `service'
@matadon
Owner
matadon commented Apr 3, 2012

On Mar 31, 2012, at 6:57 AM, Carl Hörberg wrote:

i've done some benchmarks against different app servers, and i notice that Mizuno (unlike any other app server i've tested) starts to throw undefined method exceptions on either high load (100 connections for ~40 sec) with few threads (--threads 20) or almost immediately on many threads and 100 concurrent connections.

Thanks for the amazingly detailed bug report; I'm looking into it...

@matadon
Owner
matadon commented Apr 3, 2012

This looks like a jruby --1.9-related problem (it doesn't happen if you're running with the default --1.8 flag), so I'm still working on tracking it down.

Would you mind sending me your JVM and JRuby versions as well?

@carlhoerberg
$ jruby -v
jruby 1.6.7 (ruby-1.9.2-p312) (2012-02-22 3e82bc8) (Java HotSpot(TM) Client VM 1.6.0_29) [darwin-i386-java]
@matadon
Owner
matadon commented Apr 29, 2012

This looks like it may have been related to a Jetty issue; updating Mizuno to the latest version of Jetty has fixed it on my end.

Let me know if it's stil a problem after you've updated to 0.6.3 and I'll take a deeper look.

@matadon matadon closed this Apr 29, 2012
@azell
Contributor
azell commented May 1, 2012

I can see the following error consistently:

ArgumentError (A secret is required to generate an integrity hash for cookie session data. Use config.secret_token = "some secret phrase of at least 30 characters"in config/initializers/secret_token.rb):

There appears to be some threads that see nil for MyApp.config.secret_token instead of the constant value. Tested with 0.6.3, JRuby 1.6.7.2 and Java 1.6.0_26. mizuno --env "$RACK_ENV" --threads 25

There is a race condition in Application.env_config. Will check with the JRuby and Rails guys.

Just for completeness: https://gist.github.com/rails/rails/issues/5824

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment