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

Already on GitHub? Sign in to your account

Template compilation isn't threadsafe #6400

Closed
pinetops opened this Issue May 19, 2012 · 1 comment

Comments

Projects
None yet
3 participants
Contributor

pinetops commented May 19, 2012

In a multi-threaded environment, template compilation can occur concurrently, sometimes causing an issue where the method_name stored for a template doesn't exist for all subsequent requests.

To replicate, create a rails template app with a single controller with a single action, with a single view for that action. Run the application under JRuby 1.6.7.

Use a load testing tool such as Siege to simulate high load during start up of the application.

The request fails with the following stacktrace:

ActionView::Template::Error (undefined method `_app_views_main_index_html_erb___2022471980_2026' for #<#<Class:0x3cf720d5>:0x10bdbe4f>):
  org/jruby/RubyKernel.java:2084:in `send'
  vendor/rails/actionpack/lib/action_view/template.rb:147:in `render'
  vendor/rails/activesupport/lib/active_support/notifications.rb:125:in `instrument'
  vendor/rails/actionpack/lib/action_view/template.rb:142:in `render'
  vendor/rails/actionpack/lib/action_view/renderer/template_renderer.rb:47:in `render_template'
  vendor/rails/actionpack/lib/action_view/renderer/abstract_renderer.rb:38:in `instrument'
  vendor/rails/activesupport/lib/active_support/notifications.rb:123:in `instrument'
  vendor/rails/activesupport/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
  vendor/rails/activesupport/lib/active_support/notifications/instrumenter.rb:19:in `instrument'
  vendor/rails/activesupport/lib/active_support/notifications.rb:123:in `instrument'
  vendor/rails/actionpack/lib/action_view/renderer/abstract_renderer.rb:38:in `instrument'
  vendor/rails/actionpack/lib/action_view/renderer/template_renderer.rb:46:in `render_template'
  vendor/rails/actionpack/lib/action_view/renderer/template_renderer.rb:54:in `render_with_layout'
  vendor/rails/actionpack/lib/action_view/renderer/template_renderer.rb:45:in `render_template'
  vendor/rails/actionpack/lib/action_view/renderer/template_renderer.rb:18:in `render'
  vendor/rails/actionpack/lib/action_view/renderer/renderer.rb:36:in `render_template'
  vendor/rails/actionpack/lib/action_view/renderer/renderer.rb:17:in `render'
  vendor/rails/actionpack/lib/abstract_controller/rendering.rb:110:in `_render_template'
  vendor/rails/actionpack/lib/action_controller/metal/streaming.rb:225:in `_render_template'
  vendor/rails/actionpack/lib/abstract_controller/rendering.rb:103:in `render_to_body'
  vendor/rails/actionpack/lib/action_controller/metal/renderers.rb:28:in `render_to_body'
  vendor/rails/actionpack/lib/action_controller/metal/compatibility.rb:50:in `render_to_body'
  vendor/rails/actionpack/lib/abstract_controller/rendering.rb:88:in `render'
  vendor/rails/actionpack/lib/action_controller/metal/rendering.rb:16:in `render'
  vendor/rails/actionpack/lib/action_controller/metal/instrumentation.rb:40:in `render'
  vendor/rails/activesupport/lib/active_support/core_ext/benchmark.rb:5:in `ms'
  /usr/local/rvm/rubies/jruby-1.6.7/lib/ruby/1.8/benchmark.rb:308:in `realtime'
  vendor/rails/activesupport/lib/active_support/core_ext/benchmark.rb:5:in `ms'
  vendor/rails/actionpack/lib/action_controller/metal/instrumentation.rb:40:in `render'
  vendor/rails/actionpack/lib/action_controller/metal/instrumentation.rb:83:in `cleanup_view_runtime'
  vendor/rails/activerecord/lib/active_record/railties/controller_runtime.rb:24:in `cleanup_view_runtime'
  vendor/rails/actionpack/lib/action_controller/metal/instrumentation.rb:39:in `render'
  vendor/rails/actionpack/lib/action_controller/metal/implicit_render.rb:10:in `default_render'
  vendor/rails/actionpack/lib/action_controller/metal/implicit_render.rb:5:in `send_action'
  vendor/rails/actionpack/lib/abstract_controller/base.rb:167:in `process_action'
  vendor/rails/actionpack/lib/action_controller/metal/rendering.rb:10:in `process_action'
  vendor/rails/actionpack/lib/abstract_controller/callbacks.rb:18:in `process_action'
  vendor/rails/activesupport/lib/active_support/callbacks.rb:417:in `_run__151149260__process_action__878624289__callbacks'
  org/jruby/RubyKernel.java:2076:in `send'
  vendor/rails/activesupport/lib/active_support/callbacks.rb:405:in `__run_callback'
  vendor/rails/activesupport/lib/active_support/callbacks.rb:390:in `_run_process_action_callbacks'
  org/jruby/RubyKernel.java:2080:in `send'
  vendor/rails/activesupport/lib/active_support/callbacks.rb:81:in `run_callbacks'
  vendor/rails/actionpack/lib/abstract_controller/callbacks.rb:17:in `process_action'
  vendor/rails/actionpack/lib/action_controller/metal/rescue.rb:29:in `process_action'
  vendor/rails/actionpack/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
  vendor/rails/activesupport/lib/active_support/notifications.rb:123:in `instrument'
  vendor/rails/activesupport/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
  vendor/rails/activesupport/lib/active_support/notifications/instrumenter.rb:19:in `instrument'
  vendor/rails/activesupport/lib/active_support/notifications.rb:123:in `instrument'
  vendor/rails/actionpack/lib/action_controller/metal/instrumentation.rb:29:in `process_action'
  vendor/rails/actionpack/lib/action_controller/metal/params_wrapper.rb:205:in `process_action'
  vendor/rails/activerecord/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
  vendor/rails/actionpack/lib/abstract_controller/base.rb:121:in `process'
  vendor/rails/actionpack/lib/abstract_controller/rendering.rb:45:in `process'
  vendor/rails/actionpack/lib/action_controller/metal.rb:203:in `dispatch'
  vendor/rails/actionpack/lib/action_controller/metal/rack_delegation.rb:14:in `dispatch'
  vendor/rails/actionpack/lib/action_controller/metal.rb:246:in `action'
  org/jruby/RubyProc.java:270:in `call'
  org/jruby/RubyProc.java:220:in `call'
  vendor/rails/actionpack/lib/action_dispatch/routing/route_set.rb:73:in `dispatch'
  vendor/rails/actionpack/lib/action_dispatch/routing/route_set.rb:36:in `call'
  journey (1.0.3) lib/journey/router.rb:68:in `call'
  org/jruby/RubyArray.java:1615:in `each'
  journey (1.0.3) lib/journey/router.rb:56:in `call'
  vendor/rails/actionpack/lib/action_dispatch/routing/route_set.rb:600:in `call'
  vendor/rails/actionpack/lib/action_dispatch/middleware/best_standards_support.rb:17:in `call'
  rack (1.4.1) lib/rack/etag.rb:23:in `call'
  rack (1.4.1) lib/rack/conditionalget.rb:25:in `call'
  vendor/rails/actionpack/lib/action_dispatch/middleware/head.rb:14:in `call'
  vendor/rails/actionpack/lib/action_dispatch/middleware/params_parser.rb:21:in `call'
  vendor/rails/actionpack/lib/action_dispatch/middleware/flash.rb:242:in `call'
  rack (1.4.1) lib/rack/session/abstract/id.rb:205:in `context'
  rack (1.4.1) lib/rack/session/abstract/id.rb:200:in `call'
  vendor/rails/actionpack/lib/action_dispatch/middleware/cookies.rb:338:in `call'
  vendor/rails/activerecord/lib/active_record/query_cache.rb:64:in `call'
  vendor/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:467:in `call'
  vendor/rails/actionpack/lib/action_dispatch/middleware/callbacks.rb:28:in `call'
  vendor/rails/activesupport/lib/active_support/callbacks.rb:408:in `_run__1848505450__call__1447456541__callbacks'
  org/jruby/RubyKernel.java:2076:in `send'
  vendor/rails/activesupport/lib/active_support/callbacks.rb:405:in `__run_callback'
  vendor/rails/activesupport/lib/active_support/callbacks.rb:390:in `_run_call_callbacks'
  org/jruby/RubyKernel.java:2076:in `send'
  vendor/rails/activesupport/lib/active_support/callbacks.rb:81:in `run_callbacks'
  vendor/rails/actionpack/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
  vendor/rails/actionpack/lib/action_dispatch/middleware/remote_ip.rb:31:in `call'
  vendor/rails/actionpack/lib/action_dispatch/middleware/debug_exceptions.rb:16:in `call'
  vendor/rails/actionpack/lib/action_dispatch/middleware/show_exceptions.rb:56:in `call'
  vendor/rails/railties/lib/rails/rack/logger.rb:26:in `call_app'
  vendor/rails/railties/lib/rails/rack/logger.rb:16:in `call'
  vendor/rails/actionpack/lib/action_dispatch/middleware/request_id.rb:22:in `call'
  rack (1.4.1) lib/rack/methodoverride.rb:21:in `call'
  rack (1.4.1) lib/rack/runtime.rb:17:in `call'
  vendor/rails/activesupport/lib/active_support/cache/strategy/local_cache.rb:72:in `call'
  rack-cache (1.2) lib/rack/cache/context.rb:136:in `forward'
  rack-cache (1.2) lib/rack/cache/context.rb:245:in `fetch'
  rack-cache (1.2) lib/rack/cache/context.rb:185:in `lookup'
  rack-cache (1.2) lib/rack/cache/context.rb:66:in `call!'
  rack-cache (1.2) lib/rack/cache/context.rb:51:in `call'
  vendor/rails/railties/lib/rails/engine.rb:479:in `call'
  vendor/rails/railties/lib/rails/application.rb:220:in `call'
  rack (1.4.1) lib/rack/content_length.rb:14:in `call'
  vendor/rails/railties/lib/rails/rack/log_tailer.rb:14:in `call'
  rack (1.4.1) lib/rack/handler/webrick.rb:59:in `service'
  /usr/local/rvm/rubies/jruby-1.6.7/lib/ruby/1.8/webrick/httpserver.rb:104:in `service'
  /usr/local/rvm/rubies/jruby-1.6.7/lib/ruby/1.8/webrick/httpserver.rb:65:in `run'
  /usr/local/rvm/rubies/jruby-1.6.7/lib/ruby/1.8/webrick/httpserver.rb:48:in `run'
  /usr/local/rvm/rubies/jruby-1.6.7/lib/ruby/1.8/webrick/server.rb:173:in `start_thread'
  /usr/local/rvm/rubies/jruby-1.6.7/lib/ruby/1.8/webrick/server.rb:163:in `start_thread'
  org/jruby/RubyProc.java:270:in `call'
  org/jruby/RubyProc.java:224:in `call'

Note that it doesn't always fail. Like many threading related issues this is a somewhat random occurence.

This has been replicated using both Tomcat and Webrick, and with rails 3.1.4 and 3.2.3-rc2. And using JRuby 1.6.5 and 1.6.7.

I will attach a patch that addresses this issue.

Contributor

atambo commented May 20, 2012

+1, I've hit this issue many times with jruby + tomcat startup under load.

pinetops added a commit to pinetops/rails that referenced this issue May 20, 2012

@josevalim josevalim closed this in 565c1b0 May 20, 2012

pinetops added a commit to pinetops/rails that referenced this issue May 21, 2012

Prevent concurrent compilation of templates - closes #6400
This addresses an issue where in multi-threaded environments
multiple threads can attempt to compile a template at the same time,
which occasionally causes particular templates to end up in a bad
state.

So, add synchronization such that only a single thread can attempt to
compile a template at one time.

shaynekang pushed a commit to shaynekang/rails that referenced this issue Jun 20, 2012

Merge pull request #6426 from pinetops/template_concurrency_master
Prevent concurrent compilation of templates - closes #6400
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment