rails
RuntimeError - can't add a new key into hash during iteration
Got this backtrace in development mode while using my app... The page crashed instead of rendering. Haven't managed to reproduce it though. Tried a few times, both with and without clearing the cache first.
RuntimeError - can't add a new key into hash during iteration:
/Users/bronson/.rubies/ruby-2.2.2/lib/ruby/2.2.0/set.rb:151:in `replace'
/Users/bronson/.rubies/ruby-2.2.2/lib/ruby/2.2.0/set.rb:347:in `collect!'
sprockets (3.5.2) lib/sprockets/loader.rb:85:in `asset_from_cache'
sprockets (3.5.2) lib/sprockets/loader.rb:57:in `block in load'
sprockets (3.5.2) lib/sprockets/loader.rb:312:in `block in fetch_asset_from_dependency_cache'
sprockets (3.5.2) lib/sprockets/loader.rb:308:in `fetch_asset_from_dependency_cache'
sprockets (3.5.2) lib/sprockets/loader.rb:44:in `load'
sprockets (3.5.2) lib/sprockets/cached_environment.rb:20:in `block in initialize'
sprockets (3.5.2) lib/sprockets/cached_environment.rb:47:in `load'
sprockets (3.5.2) lib/sprockets/base.rb:66:in `find_asset'
sprockets (3.5.2) lib/sprockets/base.rb:92:in `[]'
sprockets-rails (3.0.1) lib/sprockets/rails/helper.rb:342:in `find_asset'
sprockets-rails (3.0.1) lib/sprockets/rails/helper.rb:323:in `digest_path'
sprockets-rails (3.0.1) lib/sprockets/rails/helper.rb:312:in `asset_path'
sprockets-rails (3.0.1) lib/sprockets/rails/helper.rb:90:in `block in resolve_asset_path'
sprockets-rails (3.0.1) lib/sprockets/rails/helper.rb:230:in `block in resolve_asset'
sprockets-rails (3.0.1) lib/sprockets/rails/helper.rb:229:in `resolve_asset'
sprockets-rails (3.0.1) lib/sprockets/rails/helper.rb:89:in `resolve_asset_path'
sprockets-rails (3.0.1) lib/sprockets/rails/helper.rb:79:in `compute_asset_path'
actionview (5.0.0.beta2) lib/action_view/helpers/asset_url_helper.rb:144:in `asset_path'
actionview (5.0.0.beta2) lib/action_view/helpers/asset_url_helper.rb:281:in `stylesheet_path'
sprockets-rails (3.0.1) lib/sprockets/rails/helper.rb:161:in `block (2 levels) in stylesheet_link_tag'
sprockets-rails (3.0.1) lib/sprockets/rails/helper.rb:160:in `block in stylesheet_link_tag'
sprockets-rails (3.0.1) lib/sprockets/rails/helper.rb:157:in `stylesheet_link_tag'
app/views/layouts/print.html.haml:9:in `_app_views_layouts_print_html_haml__1453697812607104007_70324318851660'
actionview (5.0.0.beta2) lib/action_view/template.rb:159:in `block in render'
activesupport (5.0.0.beta2) lib/active_support/notifications.rb:166:in `instrument'
actionview (5.0.0.beta2) lib/action_view/template.rb:353:in `instrument'
actionview (5.0.0.beta2) lib/action_view/template.rb:157:in `render'
actionview (5.0.0.beta2) lib/action_view/renderer/template_renderer.rb:66:in `render_with_layout'
actionview (5.0.0.beta2) lib/action_view/renderer/template_renderer.rb:52:in `render_template'
actionview (5.0.0.beta2) lib/action_view/renderer/template_renderer.rb:14:in `render'
actionview (5.0.0.beta2) lib/action_view/renderer/renderer.rb:42:in `render_template'
actionview (5.0.0.beta2) lib/action_view/renderer/renderer.rb:23:in `render'
actionview (5.0.0.beta2) lib/action_view/rendering.rb:103:in `_render_template'
actionpack (5.0.0.beta2) lib/action_controller/metal/streaming.rb:217:in `_render_template'
actionview (5.0.0.beta2) lib/action_view/rendering.rb:83:in `render_to_body'
actionpack (5.0.0.beta2) lib/action_controller/metal/rendering.rb:52:in `render_to_body'
actionpack (5.0.0.beta2) lib/action_controller/metal/renderers.rb:144:in `render_to_body'
actionpack (5.0.0.beta2) lib/abstract_controller/rendering.rb:25:in `render'
actionpack (5.0.0.beta2) lib/action_controller/metal/rendering.rb:36:in `render'
actionpack (5.0.0.beta2) lib/action_controller/metal/instrumentation.rb:43:in `block (2 levels) in render'
activesupport (5.0.0.beta2) lib/active_support/core_ext/benchmark.rb:12:in `block in ms'
/Users/bronson/.rubies/ruby-2.2.2/lib/ruby/2.2.0/benchmark.rb:303:in `realtime'
activesupport (5.0.0.beta2) lib/active_support/core_ext/benchmark.rb:12:in `ms'
actionpack (5.0.0.beta2) lib/action_controller/metal/instrumentation.rb:43:in `block in render'
actionpack (5.0.0.beta2) lib/action_controller/metal/instrumentation.rb:86:in `cleanup_view_runtime'
activerecord (5.0.0.beta2) lib/active_record/railties/controller_runtime.rb:25:in `cleanup_view_runtime'
actionpack (5.0.0.beta2) lib/action_controller/metal/instrumentation.rb:42:in `render'
app/controllers/comparisons_controller.rb:13:in `print'
actionpack (5.0.0.beta2) lib/action_controller/metal/basic_implicit_render.rb:4:in `send_action'
actionpack (5.0.0.beta2) lib/abstract_controller/base.rb:183:in `process_action'
actionpack (5.0.0.beta2) lib/action_controller/metal/rendering.rb:30:in `process_action'
actionpack (5.0.0.beta2) lib/abstract_controller/callbacks.rb:20:in `block in process_action'
activesupport (5.0.0.beta2) lib/active_support/callbacks.rb:126:in `call'
activesupport (5.0.0.beta2) lib/active_support/callbacks.rb:506:in `block (2 levels) in compile'
activesupport (5.0.0.beta2) lib/active_support/callbacks.rb:455:in `call'
activesupport (5.0.0.beta2) lib/active_support/callbacks.rb:101:in `__run_callbacks__'
activesupport (5.0.0.beta2) lib/active_support/callbacks.rb:750:in `_run_process_action_callbacks'
activesupport (5.0.0.beta2) lib/active_support/callbacks.rb:90:in `run_callbacks'
actionpack (5.0.0.beta2) lib/abstract_controller/callbacks.rb:19:in `process_action'
actionpack (5.0.0.beta2) lib/action_controller/metal/rescue.rb:27:in `process_action'
actionpack (5.0.0.beta2) lib/action_controller/metal/instrumentation.rb:31:in `block in process_action'
activesupport (5.0.0.beta2) lib/active_support/notifications.rb:164:in `block in instrument'
activesupport (5.0.0.beta2) lib/active_support/notifications/instrumenter.rb:21:in `instrument'
activesupport (5.0.0.beta2) lib/active_support/notifications.rb:164:in `instrument'
actionpack (5.0.0.beta2) lib/action_controller/metal/instrumentation.rb:29:in `process_action'
actionpack (5.0.0.beta2) lib/action_controller/metal/params_wrapper.rb:248:in `process_action'
activerecord (5.0.0.beta2) lib/active_record/railties/controller_runtime.rb:18:in `process_action'
actionpack (5.0.0.beta2) lib/abstract_controller/base.rb:128:in `process'
actionview (5.0.0.beta2) lib/action_view/rendering.rb:30:in `process'
actionpack (5.0.0.beta2) lib/action_controller/metal.rb:193:in `dispatch'
actionpack (5.0.0.beta2) lib/action_controller/metal.rb:265:in `dispatch'
actionpack (5.0.0.beta2) lib/action_dispatch/routing/route_set.rb:50:in `dispatch'
actionpack (5.0.0.beta2) lib/action_dispatch/routing/route_set.rb:32:in `serve'
actionpack (5.0.0.beta2) lib/action_dispatch/journey/router.rb:42:in `block in serve'
actionpack (5.0.0.beta2) lib/action_dispatch/journey/router.rb:29:in `serve'
actionpack (5.0.0.beta2) lib/action_dispatch/routing/route_set.rb:724:in `call'
actionview (5.0.0.beta2) lib/action_view/digestor.rb:14:in `call'
rack (2.0.0.alpha) lib/rack/etag.rb:25:in `call'
rack (2.0.0.alpha) lib/rack/conditional_get.rb:25:in `call'
rack (2.0.0.alpha) lib/rack/head.rb:12:in `call'
actionpack (5.0.0.beta2) lib/action_dispatch/middleware/cookies.rb:608:in `call'
activerecord (5.0.0.beta2) lib/active_record/query_cache.rb:36:in `call'
activerecord (5.0.0.beta2) lib/active_record/connection_adapters/abstract/connection_pool.rb:963:in `call'
activerecord (5.0.0.beta2) lib/active_record/migration.rb:558:in `call'
actionpack (5.0.0.beta2) lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
activesupport (5.0.0.beta2) lib/active_support/callbacks.rb:97:in `__run_callbacks__'
activesupport (5.0.0.beta2) lib/active_support/callbacks.rb:750:in `_run_call_callbacks'
activesupport (5.0.0.beta2) lib/active_support/callbacks.rb:90:in `run_callbacks'
actionpack (5.0.0.beta2) lib/action_dispatch/middleware/callbacks.rb:27:in `call'
actionpack (5.0.0.beta2) lib/action_dispatch/middleware/reloader.rb:71:in `call'
actionpack (5.0.0.beta2) lib/action_dispatch/middleware/remote_ip.rb:79:in `call'
better_errors (2.1.1) lib/better_errors/middleware.rb:84:in `protected_app_call'
better_errors (2.1.1) lib/better_errors/middleware.rb:79:in `better_errors_call'
better_errors (2.1.1) lib/better_errors/middleware.rb:57:in `call'
actionpack (5.0.0.beta2) lib/action_dispatch/middleware/debug_exceptions.rb:49:in `call'
actionpack (5.0.0.beta2) lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
railties (5.0.0.beta2) lib/rails/rack/logger.rb:36:in `call_app'
railties (5.0.0.beta2) lib/rails/rack/logger.rb:24:in `block in call'
activesupport (5.0.0.beta2) lib/active_support/tagged_logging.rb:70:in `block in tagged'
activesupport (5.0.0.beta2) lib/active_support/tagged_logging.rb:26:in `tagged'
activesupport (5.0.0.beta2) lib/active_support/tagged_logging.rb:70:in `tagged'
railties (5.0.0.beta2) lib/rails/rack/logger.rb:24:in `call'
actionpack (5.0.0.beta2) lib/action_dispatch/middleware/request_id.rb:24:in `call'
rack (2.0.0.alpha) lib/rack/method_override.rb:22:in `call'
rack (2.0.0.alpha) lib/rack/runtime.rb:22:in `call'
activesupport (5.0.0.beta2) lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
actionpack (5.0.0.beta2) lib/action_dispatch/middleware/load_interlock.rb:13:in `call'
actionpack (5.0.0.beta2) lib/action_dispatch/middleware/static.rb:136:in `call'
rack (2.0.0.alpha) lib/rack/sendfile.rb:111:in `call'
railties (5.0.0.beta2) lib/rails/engine.rb:522:in `call'
rack (2.0.0.alpha) lib/rack/handler/webrick.rb:86:in `service'
/Users/bronson/.rubies/ruby-2.2.2/lib/ruby/2.2.0/webrick/httpserver.rb:138:in `service'
/Users/bronson/.rubies/ruby-2.2.2/lib/ruby/2.2.0/webrick/httpserver.rb:94:in `run'
/Users/bronson/.rubies/ruby-2.2.2/lib/ruby/2.2.0/webrick/server.rb:294:in `block in start_thread'
I am experiencing this as well. It is not consistent but I can rarely compile all assets without getting it at least once.
Looks like some kind of a race condition to me. We have a lot of small files. Perhaps the more files you need to compile the more likely you are to get this error. The code in sprockets loader.rb file performs a lot of in-place modifications. Maybe some other thread is iterating over those same keys at the same time?
Same for me:
[----] F, [2016-04-14T14:39:20.360658 #29342:196d060] FATAL -- : Error caught: [RuntimeError] can't add a new key into hash during iteration
/home/martin/.rvm/rubies/ruby-2.2.2/lib/ruby/2.2.0/set.rb:151:in `replace'
/home/martin/.rvm/rubies/ruby-2.2.2/lib/ruby/2.2.0/set.rb:151:in `replace'
/home/martin/.rvm/rubies/ruby-2.2.2/lib/ruby/2.2.0/set.rb:347:in `collect!'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/loader.rb:85:in `asset_from_cache'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/loader.rb:57:in `block in load'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/loader.rb:311:in `block in fetch_asset_from_dependency_cache'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/loader.rb:307:in `each'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/loader.rb:307:in `each_with_index'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/loader.rb:307:in `fetch_asset_from_dependency_cache'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/loader.rb:44:in `load'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/cached_environment.rb:20:in `block in initialize'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/cached_environment.rb:47:in `yield'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/cached_environment.rb:47:in `load'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/base.rb:66:in `find_asset'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-3.6.0/lib/sprockets/base.rb:92:in `[]'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:341:in `find_asset'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:322:in `digest_path'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:311:in `asset_path'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:89:in `block in resolve_asset_path'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:229:in `block in resolve_asset'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:228:in `each'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:228:in `detect'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:228:in `resolve_asset'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:88:in `resolve_asset_path'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:78:in `compute_asset_path'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/bundler/gems/rails-53ab1ee5652e/actionview/lib/action_view/helpers/asset_url_helper.rb:144:in `asset_path'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/bundler/gems/rails-53ab1ee5652e/actionview/lib/action_view/helpers/asset_url_helper.rb:281:in `stylesheet_path'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:160:in `block (2 levels) in stylesheet_link_tag'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:159:in `map'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:159:in `block in stylesheet_link_tag'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:156:in `map'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/gems/sprockets-rails-3.0.4/lib/sprockets/rails/helper.rb:156:in `stylesheet_link_tag'
/home/martin/Projects/manageiq-2/app/views/layouts/application.html.haml:26:in `_app_views_layouts_application_html_haml__2777982366737568467_70121407000000'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/bundler/gems/rails-53ab1ee5652e/actionview/lib/action_view/template.rb:158:in `block in render'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/bundler/gems/rails-53ab1ee5652e/activesupport/lib/active_support/notifications.rb:166:in `instrument'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/bundler/gems/rails-53ab1ee5652e/actionview/lib/action_view/template.rb:348:in `instrument'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/bundler/gems/rails-53ab1ee5652e/actionview/lib/action_view/template.rb:156:in `render'
/home/martin/.rvm/gems/ruby-2.2.2@cfme/bundler/gems/rails-53ab1ee5652e/actionview/lib/action_view/renderer/template_renderer.rb:66:in `render_with_layout'
Which is being tracked in https://github.com/ruby-concurrency/concurrent-ruby/issues/528
Not sure why that would happen here though. I don't think that we load assets concurrently. The error is coming from
asset = cache.get(key, true)
if asset
asset[:metadata][:dependencies].map! { |uri| uri.start_with?("file-digest://") ? expand_from_root(uri) : uri } if asset[:metadata][:dependencies]
basically.
We are mutating the values of a hash as we're iterating through it, but I would think that would either work all the time or never. It's weird that it's the same line for both of you since there are other arrays that we're mutating before. I guess maybe that asset only has dependencies?
Both of you are using Ruby 2.2.2 can you try 2.2.4 or 2.3.0?
Could one of you share a project that demonstrates this problem, even if only sometimes?
The best way to reproduce something that happens intermittently is to do it a lot. If this fails on rake assets:precompile you can loop through that, waiting for it to fail.
$ while bundle exec rake assets:precompile; do : ; done
I am sorry but I can not share the code of the project I am working on. My only observation is that the more files Sprockets needs to compile the more likely the error.
I am currently using Ruby 2.2.4 and hitting the same error.
I am sorry but I can not share the code of the project I am working on.
Sorry didn't specify, I really don't want your code. I want a small project that reproduces the problem. Like may be if the error always happens on the same asset, pull that out into a new project and see if the error happens. If it does, replace the asset with something generic and sharable. If I can't reproduce the problem with an example app, I won't be able to fix it.
Tried to repro the behavior with a ruby only script and i'm not able to
require 'set'
require 'securerandom'
while true
hash = {}
hash[:nested] = {}
hash[:nested][:set] = Set.new
rand(0..5000).times.each do |i|
puts i
hash[:nested][:set] << SecureRandom.hex.upcase
end
marshaled = Marshal.dump(hash)
new_hash = Marshal.load(marshaled)
new_hash[:nested][:set].map! {|x| x.downcase }
end
@jeremy right now assets are loaded one at a time since they have dependencies that needed to be loaded in order. Theoretically we could parallelize it but it would need some love to get to that point.
The only other way that these could be accessed parallel that I can see is if they're being accessed by two different requests at the same time. The only way that would happen is if this was in development mode, or if config.assets.compile = true.
Got this backtrace in development mode while using my app
Ah, ha. So it may be related to concurrency.
Sorry, I did not have time to make a test app.
@schneems, I am mostly seeing this problem when running browser tests in development with compilation. That involves loading the same .js files many times for each test. So it does look like multiple requests trigger concurrent access issues.
Not sure the best way to move forwards here. If the issue exists only in development we don't want to slow down prod to fix dev.
I'm still not 100% sure what is happening. It looks like maybe marshal is returning the exact same object for each request maybe?
Please try this repository. It reproduces the problem on my Mac quite reliably.
Please also note the (lack of) speed of asset compilation. Even though the number of files is large Sprockets takes ages to compile. Way too slow in my opinion. It is not uncommon to have even more dependencies in large projects if you include CSS, font and image assets. The sprockets_bug repo could also be used to research the issue #84.
Thank you!
Has anyone had any luck reproducing the issue with the demo repository? Is there some other way I could help?
I see the linked issue has been resolved and folded into the Rails 5.0.0 release, but it's not working for me in 4.2. Any ideas here?
If I understand it correctly, the bug in #24627 has been fixed by upgrading to the latest ConcurrentRuby. I upgraded the demo repository too but the problem still occurs.
Anyone have any insights on this yet? Or at least an idea of a starting point; happy to dig deeper myself!
We know exactly what is happening, it's just that to solve it would cause performance problems in production which we don't want. Maybe try using some other cache backends and see if that helps? You can try memcache, filestore, memory store.
The issue is that the same object is being mutated in several threads since you're using a multithreaded webserver in development.
One hacky work around could be to turn down your threads to 1 in development and instead use multiple processes (i.e. multiple puma workers). That should prevent this problem from showing up locally until (if) a sane fix can be applied.
RuntimeError: can't add a new key into hash during iteration
1 File "/app/.rvm/rubies/ruby-2.3.0/lib/ruby/2.3.0/set.rb" line 153 in replace
2 File "/app/.rvm/rubies/ruby-2.3.0/lib/ruby/2.3.0/set.rb" line 153 in replace
3 File "/app/.rvm/rubies/ruby-2.3.0/lib/ruby/2.3.0/set.rb" line 360 in collect!
4 File "/app/shared/bundle/ruby/2.3.0/gems/sprockets-3.6.0/lib/sprockets/loader.rb" line 85 in asset_from_cache
5 File "/app/shared/bundle/ruby/2.3.0/gems/sprockets-3.6.0/lib/sprockets/loader.rb" line 35 in load
6 File "/app/shared/bundle/ruby/2.3.0/gems/sprockets-3.6.0/lib/sprockets/cached_environment.rb" line 20 in block in initialize
7 File "/app/shared/bundle/ruby/2.3.0/gems/sprockets-3.6.0/lib/sprockets/cached_environment.rb" line 47 in load
8 File "/app/shared/bundle/ruby/2.3.0/gems/sprockets-3.6.0/lib/sprockets/legacy.rb" line 195 in block in to_a
9 File "/app/shared/bundle/ruby/2.3.0/gems/sprockets-3.6.0/lib/sprockets/legacy.rb" line 195 in map
10 File "/app/shared/bundle/ruby/2.3.0/gems/sprockets-3.6.0/lib/sprockets/legacy.rb" line 195 in to_a
11 File "/app/shared/bundle/ruby/2.3.0/gems/sprockets-3.6.0/lib/sprockets/legacy.rb" line 207 in dependencies
12 File "/app/shared/bundle/ruby/2.3.0/bundler/gems/opal-c92d78b3b443/lib/opal/sprockets.rb" line 40 in load_asset
13 File "/app/shared/bundle/ruby/2.3.0/bundler/gems/opal-rails-ddc65773ea16/app/helpers/opal_helper.rb" line 19 in block in javascript_include_tag
14 File "/app/shared/bundle/ruby/2.3.0/bundler/gems/opal-rails-ddc65773ea16/app/helpers/opal_helper.rb" line 18 in each
15 File "/app/shared/bundle/ruby/2.3.0/bundler/gems/opal-rails-ddc65773ea16/app/helpers/opal_helper.rb" line 18 in javascript_include_ta
@schneems to add context to the stacktrace above we're seeing this in production, the server in our case is Rainbows! with ThreadPool strategy which is indeed multithreaded.
This is a reduced example of what happens:
require 'set'
set = Set.new (1..5).to_a
p set
loop = -> {
set.map! do |v|
sleep 0.1
v+1
end
}
t1 = Thread.new {
sleep 0.2
loop.call
}
t2 = Thread.new {
sleep 0.1
loop.call
}
t1.join
t2.join
I think it could make sense to add an in-memory cache for assets with expanded keys, something on the lines of this:
def asset_from_cache(key)
asset = cache.get(key, true)
return unless asset
@expanded_assets ||= {} # this should be initialized elsewhere
@expanded_assets[key] ||= begin
asset[:uri] = expand_from_root(asset[:uri])
asset[:load_path] = expand_from_root(asset[:load_path])
asset[:filename] = expand_from_root(asset[:filename])
asset[:metadata][:included] = asset[:metadata][:included].map { |uri| expand_from_root(uri) } if asset[:metadata][:included]
asset[:metadata][:links] = asset[:metadata][:links].map { |uri| expand_from_root(uri) } if asset[:metadata][:links]
asset[:metadata][:stubbed] = asset[:metadata][:stubbed].map { |uri| expand_from_root(uri) } if asset[:metadata][:stubbed]
asset[:metadata][:required] = asset[:metadata][:required].map { |uri| expand_from_root(uri) } if asset[:metadata][:required]
asset[:metadata][:dependencies] = asset[:metadata][:dependencies].map { |uri| uri.start_with?("file-digest://") ? expand_from_root(uri) : uri } if asset[:metadata][:dependencies]
asset[:metadata].each_key do |k|
next unless k =~ /_dependencies\z/
asset[:metadata][k] = asset[:metadata][k].map { |uri| expand_from_root(uri) }
end
asset
end
end
It's clearly draft code but should eliminate both performance and root-expansion problems at the cost of some memory that would stay resident instead of being GC'ed and rebuilt each time.
PS: in the meanwhile I'll try this patch
I agree that PR would solve the problem, however in production we want to mutate the original arrays as there is a performance penalty for allocating additional objects.
Maybe if someone has some time and can set up some benchmarks with a large-ish project (lots of assets) and can show that this change has very little impact we could move forwards with it.
Not a super big set, but foo.js has 132 dependecies, so I think it's a fair benchmark
p setup_env[Sprockets::CachedEnvironment].find_asset('foo').metadata[:dependencies].size # => 132
(the control benchmark is there just to ensure a slower impl is detected)
gem 'opal', '0.10.0.beta5'
gem 'benchmark-ips'
gem 'sprockets', '3.6.0'
require 'opal'
require 'benchmark/ips'
class PatchedEnvironment < Sprockets::CachedEnvironment
def initialize(*)
super
@expanded_assets_cache = {}
end
def asset_from_cache(key)
return @expanded_assets_cache[key] if @expanded_assets_cache.has_key?(key)
asset = cache.get(key, true)
if asset
asset[:uri] = expand_from_root(asset[:uri])
asset[:load_path] = expand_from_root(asset[:load_path])
asset[:filename] = expand_from_root(asset[:filename])
asset[:metadata][:included] = asset[:metadata][:included].map { |uri| expand_from_root(uri) } if asset[:metadata][:included]
asset[:metadata][:links] = asset[:metadata][:links].map { |uri| expand_from_root(uri) } if asset[:metadata][:links]
asset[:metadata][:stubbed] = asset[:metadata][:stubbed].map { |uri| expand_from_root(uri) } if asset[:metadata][:stubbed]
asset[:metadata][:required] = asset[:metadata][:required].map { |uri| expand_from_root(uri) } if asset[:metadata][:required]
asset[:metadata][:dependencies] = asset[:metadata][:dependencies].map { |uri| uri.start_with?("file-digest://") ? expand_from_root(uri) : uri } if asset[:metadata][:dependencies]
asset[:metadata].each_key do |k|
next unless k =~ /_dependencies\z/
asset[:metadata][k] = asset[:metadata][k].map { |uri| expand_from_root(uri) }
end
asset
end
@expanded_assets_cache[key] = asset
end
end
class ControlEnvironment < Sprockets::CachedEnvironment
def asset_from_cache(key)
sleep 0.01
super
end
end
dirs = Opal.paths
files = Dir["{#{dirs.join(',')}}/*.rb"]
names = files.map { |path| File.basename(path, '.rb') }
File.write "#{__dir__}/foo.js", names.map {|n| "//= depend_on #{n}.js\n"}.join
names << 'foo'
env = Sprockets::Environment.new(__dir__)
env.cache = Sprockets::Cache::FileStore.new('cache')
(dirs + [__dir__]).each { |path| env.append_path path }
setup_env = -> klass { klass.new(env) }
Benchmark.ips do |x|
x.report("vanilla") { setup_env[Sprockets::CachedEnvironment].find_asset('foo.js') }
x.report("patched") { setup_env[PatchedEnvironment].find_asset('foo.js') }
x.report("control") { setup_env[ControlEnvironment].find_asset('foo.js') }
x.compare!
end
Warming up --------------------------------------
vanilla 20.000 i/100ms
patched 16.000 i/100ms
control 5.000 i/100ms
Calculating -------------------------------------
vanilla 211.511 (±13.7%) i/s - 1.040k
patched 211.118 (±17.5%) i/s - 1.024k
control 50.642 (± 5.9%) i/s - 255.000
Comparison:
vanilla: 211.5 i/s
patched: 211.1 i/s - same-ish: difference falls within error
control: 50.6 i/s - 4.18x slower
It's all self contained, you can save the script to something like /tmp/bench.rb and just run it. :)
We're seeing this issue in production running on jruby 1.7.24 (1.9.3p551) with puma 2.15.x. We're actually encountering it when we use the image_tag helper and it dives down into sprockets to locate an asset (yes, we have the sprockets runtime enabled in production at the moment).
when you said:
Maybe try using some other cache backends and see if that helps? You can try memcache, filestore, memory store.
Do you mean that we should consider configuring rails to use a different cache backend? e.g. config.cache_store = :memory_store? Or is there a sprockets-specific cache backend? I don't understand exactly where the cache backend fits into this (sorry for my ignorance, I'm still trying to grok the internals of sprockets).
I'd love to throw together an example app for you, but it's been surprisingly hard to reproduce. I will see what I can do though.
