Rails - erratic Timeout errors possibly tied to asset compilation

Question

Preemptive apologies for the code dump. I've been banging my head against this one for a while (and doing a ton of Googling) and just have a pretty fuzzy idea what is and isn't relevant, and how to fix things. So I figured I'd get as much info as possible out there. Please let me know if there's anything else I should add that might be helpful. Thanks!

I'm starting up a Rails and Angular app and mostly still in development mode. I'm using Heroku, but I don't know if these issues are serious there as well, cause I've mostly been coding and bumping into them on local (have barely poked around on production). (Just mentioned, because most similar questions seem to be Heroku-specific).

The error I keep intermittently bumping into is this one:

 Rack::Timeout::RequestTimeoutError: Request ran for longer than 5 seconds.

and its doppelganger:

 ActionView::Template::Error: Request ran for longer than 5 seconds.

When it's raised, it points to different files as the immediate culprit -- but always a Java/CoffeeScript or CSS/SASS file. Occasionally reloading the browser on the local server will pinwheel eternally instead of raising the above error. Often, a refresh will work fine, but occasionally I have to restart the server to "unfreeze" it.

I could try increasing the Rack::Timeout to something larger, but it strikes me that that would be treating one of potentially many symptoms, rather than the underlying problem.

I'm convinced this has something to do with an asset precompilation mistake of some sort -- which I'm new to, as this is my first serious app from scratch, particularly combining Angular and Rails.

I've had a hard time finding really smooth combinations of Rails and Angular -- advice is definitely appreciated.

I've managed to pinpoint the error by running and rerunning some feature specs while messing with my manifest SASS file. Every time I change the application.sass file by commenting some @imports out, (some of) the feature specs fail, but if I re-run them, they pass again and again, until I comment in or out a different line. The specific line(s) don't seem relevant, but, just in case I'm wrong, here's my application.sass file:

@charset "utf-8"

@import "bootstrap-sprockets"
@import "bootstrap"

@import "bourbon"
@import "base/grid-settings"
@import "neat"
@import "base/base"

@import "leaflet"

@import "skeleton/base"
@import "skeleton/layout"
@import "skeleton/skeleton"

@import "sections/header"
@import "sections/footer"
@import "sections/user"
@import "sections/map"
@import "sections/tabs"

@import "sections/baseapp"

@import "markercluster/MarkerCluster"
@import "markercluster/MarkerCluster.Default"

@import "icons"

@import "font-awesome-sprockets"
@import "font-awesome"

Because I think my messy asset solution is possibly to blame, I'll paste most of the relevant code below. Basically, I'm using NPM (package.json) for server-side JS stuff like Jasmine for testing, and Bower for client-side stuff like Angular and Leaflet (for maps). To make the Bower JS available in the Rails app, I'm using Rails Assets in my Gemfile. (Though I don't get why I need the bower.json stuff if I'm doing that). So the relevant parts of those manifest files look like this:

package.json

{
  "name": "whatever",
  "dependencies": {
    "rosie": "0.2.0",    
    "bower": "1.2.8",
    "jasmine": "2.1.1",
    "phantomjs": "1.9.13",
    "sinon": "1.12.2",
    "jasmine-sinon": "0.4.0",
    "requirejs": "2.1.15"
  },
  "devDependencies": {
    "grunt": "~0.4.4"
  }
}

bower.json

{
  "name": "whatever",
  "version": "0.1.0",
  "authors": [
    "Whatever"
  ],
  "ignore": [
    "**/.*",
    "node_modules",
    "bower_compnents",
    "test",
    "tests"
  ],
  "dependencies": {
    "angular": "latest",
    "angular-resource": "latest",
    "angular-route": "latest",
    "angular-mocks": "latest",
    "active-support": "latest",
    "async": "latest",
    "lodash": "latest",
    "leaflet": "latest",
    "leaflet.markercluster": "latest"
  }
}

I mean to tie down the versions before putting this in front of users.

Gemfile

gem 'rails-assets-angular'
gem 'rails-assets-angular-resource'
gem 'rails-assets-angular-route'
gem 'rails-assets-angular-mocks'
gem 'rails-assets-active-support'
gem 'rails-assets-async'
gem 'rails-assets-lodash'
gem 'rails-assets-leaflet'
gem 'rails-assets-requirejs'
gem 'rails-assets-sinon'
# gem 'rails-assets-leaflet.markercluster' -- wasn't working, so I included the relevant scripts in app/assets/javascripts/ -- seems to be working

我也在test我的Gemfile组中添加了这些.我担心这些JS包含的重叠和蔓延,但这是让JS测试工作的原因.

  gem "jasmine-rails"
  gem 'jasmine-headless-webkit'
  gem 'guard-jasmine'
  gem 'rails-assets-rosie'
  gem "sinon-rails"

由于各种原因,我手动预编译了一些资产:

配置/初始化/ assets.rb

Rails.application.config.assets.precompile += [ 
  'api/bookmarklets/view.js', 
  'sections/bookmarklet.css',   
  'icons.eot',
  'icons.svg',
  'icons.ttf',
  'icons.woff'
]

在本地,(现在正在生产),我的资产只是托管在服务器上(所以localhost:3000).怀疑数据库是相关的,但它的池被设置为2和超时5000.搜索其他可能相关的代码,我发现这config/environments/development.rb可能是问题？:

  # Debug mode disables concatenation and preprocessing of assets.
  # This option may cause significant delays in view rendering with a large
  # number of complex assets.
  config.assets.debug = true

编辑 - 在运行功能规范时从我遇到的一个错误中添加完整的堆栈跟踪:

# /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sass-3.2.19/lib/sass/scss/parser.rb:125:in `[]'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sass-3.2.19/lib/sass/scss/parser.rb:125:in `process_comment'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sass-3.2.19/lib/sass/scss/parser.rb:88:in `s'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sass-3.2.19/lib/sass/scss/parser.rb:82:in `block in stylesheet'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sass-3.2.19/lib/sass/scss/parser.rb:545:in `block_contents'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sass-3.2.19/lib/sass/scss/parser.rb:82:in `stylesheet'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sass-3.2.19/lib/sass/scss/parser.rb:27:in `parse'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sass-3.2.19/lib/sass/engine.rb:342:in `_to_tree'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sass-3.2.19/lib/sass/engine.rb:315:in `_render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sass-3.2.19/lib/sass/engine.rb:262:in `render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/sass_compressor.rb:24:in `evaluate'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/tilt-1.4.1/lib/tilt/template.rb:103:in `render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/context.rb:197:in `block in evaluate'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/context.rb:194:in `each'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/context.rb:194:in `evaluate'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/bundled_asset.rb:25:in `initialize'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/base.rb:377:in `new'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/base.rb:377:in `build_asset'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/index.rb:94:in `block in build_asset'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/caching.rb:58:in `cache_asset'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/index.rb:93:in `build_asset'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/base.rb:287:in `find_asset'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/index.rb:61:in `find_asset'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-2.12.3/lib/sprockets/base.rb:295:in `[]'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-rails-2.2.2/lib/sprockets/rails/helper.rb:123:in `asset_digest_path'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-rails-2.2.2/lib/sprockets/rails/helper.rb:76:in `compute_asset_path'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/helpers/asset_url_helper.rb:132:in `asset_path'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-rails-2.2.2/lib/sprockets/rails/helper.rb:91:in `asset_path'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/helpers/asset_url_helper.rb:256:in `stylesheet_path'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/helpers/asset_tag_helper.rb:100:in `block in stylesheet_link_tag'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/helpers/asset_tag_helper.rb:96:in `map'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/helpers/asset_tag_helper.rb:96:in `stylesheet_link_tag'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/sprockets-rails-2.2.2/lib/sprockets/rails/helper.rb:170:in `stylesheet_link_tag'
 # ./app/views/layouts/application.html.haml:9:in `_app_views_layouts_application_html_haml__3935206380113339538_2226830520'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/template.rb:145:in `block in render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/notifications.rb:161:in `instrument'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/template.rb:339:in `instrument'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/template.rb:143:in `render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-mini-profiler-0.9.2/lib/mini_profiler/profiling_methods.rb:79:in `block in profile_method'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/renderer/template_renderer.rb:67:in `render_with_layout'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/renderer/template_renderer.rb:53:in `render_template'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/renderer/template_renderer.rb:17:in `render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/renderer/renderer.rb:42:in `render_template'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/renderer/renderer.rb:23:in `render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/rendering.rb:99:in `_render_template'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/streaming.rb:217:in `_render_template'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/rendering.rb:82:in `render_to_body'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/rendering.rb:32:in `render_to_body'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/renderers.rb:32:in `render_to_body'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/abstract_controller/rendering.rb:25:in `render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/rendering.rb:16:in `render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/instrumentation.rb:41:in `block (2 levels) in render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/core_ext/benchmark.rb:12:in `block in ms'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/core_ext/benchmark.rb:12:in `ms'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/instrumentation.rb:41:in `block in render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/instrumentation.rb:84:in `cleanup_view_runtime'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activerecord-4.1.4/lib/active_record/railties/controller_runtime.rb:25:in `cleanup_view_runtime'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/instrumentation.rb:40:in `render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/implicit_render.rb:10:in `default_render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/responder.rb:238:in `default_render'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/responder.rb:165:in `to_html'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/responder.rb:158:in `respond'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/responder.rb:151:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/mime_responds.rb:400:in `respond_with'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/devise-3.4.1/app/controllers/devise/sessions_controller.rb:11:in `new'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/abstract_controller/base.rb:189:in `process_action'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/rendering.rb:10:in `process_action'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/abstract_controller/callbacks.rb:20:in `block in process_action'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:113:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:113:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:149:in `block in halting_and_conditional'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:229:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:229:in `block in halting'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:166:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:166:in `block in halting'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:166:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:166:in `block in halting'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:166:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:166:in `block in halting'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:149:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:149:in `block in halting_and_conditional'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:149:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:149:in `block in halting_and_conditional'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:149:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:149:in `block in halting_and_conditional'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:149:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:149:in `block in halting_and_conditional'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:86:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:86:in `run_callbacks'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/abstract_controller/callbacks.rb:19:in `process_action'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/rescue.rb:29:in `process_action'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/instrumentation.rb:31:in `block in process_action'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/notifications.rb:159:in `block in instrument'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/notifications.rb:159:in `instrument'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/params_wrapper.rb:250:in `process_action'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activerecord-4.1.4/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/abstract_controller/base.rb:136:in `process'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionview-4.1.4/lib/action_view/rendering.rb:30:in `process'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-mini-profiler-0.9.2/lib/mini_profiler/profiling_methods.rb:79:in `block in profile_method'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal.rb:196:in `dispatch'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal/rack_delegation.rb:13:in `dispatch'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_controller/metal.rb:232:in `block in action'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/routing/route_set.rb:82:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/routing/route_set.rb:82:in `dispatch'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/routing/route_set.rb:50:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/routing/mapper.rb:45:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/journey/router.rb:71:in `block in call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/journey/router.rb:59:in `each'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/journey/router.rb:59:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/routing/route_set.rb:678:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/warden-1.2.3/lib/warden/manager.rb:35:in `block in call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/warden-1.2.3/lib/warden/manager.rb:34:in `catch'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/warden-1.2.3/lib/warden/manager.rb:34:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/etag.rb:23:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/conditionalget.rb:25:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/head.rb:11:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/middleware/params_parser.rb:27:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/middleware/flash.rb:254:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/session/abstract/id.rb:225:in `context'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/session/abstract/id.rb:220:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/middleware/cookies.rb:560:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activerecord-4.1.4/lib/active_record/query_cache.rb:36:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activerecord-4.1.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:621:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/callbacks.rb:82:in `run_callbacks'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/middleware/remote_ip.rb:76:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/airbrake-4.1.0/lib/airbrake/rails/middleware.rb:13:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/railties-4.1.4/lib/rails/rack/logger.rb:38:in `call_app'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/railties-4.1.4/lib/rails/rack/logger.rb:20:in `block in call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/tagged_logging.rb:68:in `block in tagged'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/tagged_logging.rb:26:in `tagged'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/tagged_logging.rb:68:in `tagged'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/railties-4.1.4/lib/rails/rack/logger.rb:20:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/request_store-1.1.0/lib/request_store/middleware.rb:8:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/middleware/request_id.rb:21:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/methodoverride.rb:21:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/runtime.rb:17:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/activesupport-4.1.4/lib/active_support/cache/strategy/local_cache_middleware.rb:26:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/actionpack-4.1.4/lib/action_dispatch/middleware/static.rb:64:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/sendfile.rb:112:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/airbrake-4.1.0/lib/airbrake/user_informer.rb:16:in `_call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/airbrake-4.1.0/lib/airbrake/user_informer.rb:12:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-timeout-0.1.1/lib/rack/timeout.rb:104:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-mini-profiler-0.9.2/lib/mini_profiler/profiler.rb:193:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/railties-4.1.4/lib/rails/engine.rb:514:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/railties-4.1.4/lib/rails/application.rb:144:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/builder.rb:138:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/urlmap.rb:65:in `block in call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/urlmap.rb:50:in `each'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-1.5.2/lib/rack/urlmap.rb:50:in `call'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-test-0.6.3/lib/rack/mock_session.rb:30:in `request'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-test-0.6.3/lib/rack/test.rb:244:in `process_request'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/rack-test-0.6.3/lib/rack/test.rb:58:in `get'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/capybara-2.4.4/lib/capybara/rack_test/browser.rb:60:in `process'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/capybara-2.4.4/lib/capybara/rack_test/browser.rb:38:in `block in process_and_follow_redirects'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/capybara-2.4.4/lib/capybara/rack_test/browser.rb:37:in `times'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/capybara-2.4.4/lib/capybara/rack_test/browser.rb:37:in `process_and_follow_redirects'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/capybara-2.4.4/lib/capybara/rack_test/browser.rb:21:in `visit'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/capybara-2.4.4/lib/capybara/rack_test/driver.rb:42:in `visit'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/capybara-2.4.4/lib/capybara/session.rb:227:in `visit'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/capybara-2.4.4/lib/capybara/dsl.rb:51:in `block (2 levels) in <module:DSL>'
 # ./spec/features/authentication_spec.rb:7:in `block (3 levels) in <top (required)>'
 # ./spec/support/background_jobs.rb:14:in `block (3 levels) in <top (required)>'
 # ./spec/support/background_jobs.rb:5:in `run_background_jobs_immediately'
 # ./spec/support/background_jobs.rb:13:in `block (2 levels) in <top (required)>'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/zeus-0.15.2/lib/zeus/rails.rb:208:in `test'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/zeus-0.15.2/lib/zeus.rb:148:in `block in command'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/zeus-0.15.2/lib/zeus.rb:135:in `fork'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/zeus-0.15.2/lib/zeus.rb:135:in `command'
 # /Users/sasha/.rvm/gems/ruby-2.1.2/gems/zeus-0.15.2/lib/zeus.rb:50:in `go'

更新

Following coreyward's advice, I set the Rack timeout to 25 seconds and set up some profiling tools. The increase in the timeout (which was dev-environment specific) made the problem go away on localhost. But, perplexingly, I didn't seem to experience any load times of 5+ seconds at all, according to NewRelic and MiniProfiler. I think the longest load time I got was around 3 seconds, and I only got that once. I improved a query, and didn't bump into load times that high again. So it's weird that I bumped into that 5-second limit.

Basically, the load time problem seemed to disappear when I increased the Rack timeout. But I there's still something weird going on, cause the feature tests will still time out in Continuous Integration tests and occasionally on local .

I since cleaned up my asset situation (got rid of Bower and NPM, and did everything through the Gemfile, usually using the Rails-Assets gem). I also upgraded to Rails 4.2 and Ruby 2.2 for performance enhancements. Things generally appear to load a bit faster, according to profiling.

But I'm still getting the same test failures. Interestingly, on my Continuous Integration tool, the tests pretty much always fail, and when they do, they fail with a different error (I captured with a screenshot).

Internal Server Error

could not obtain a database connection within 5.000 seconds (waited 5.000 seconds)

________________________________

WEBrick/1.3.1 (Ruby/2.2.0/2014-12-25) at 127.0.0.1:47539

This suggests it's a DB issue. My DB set up (database.yml) for the Test environment (which my CI uses) is below:

  adapter: postgresql
  database: planit_development
  encoding: utf8
  host: localhost
  min_messages: warning
  pool: 2
  timeout: 5000

But, weirdly, my local test suite, which has the same settings, tends to pass (unless I mess with an asset file, in which case there's a chance a feature spec will fail on the first, but not subsequent, run(s)). And the tests that are failing are the least database-intensive tests in the whole suite (just basic auth flow testing).

The profiling definitely helped me fix some mistakes, but I'm still pretty stumped here about what's the root cause of what appears to be a continuing problem. Any ideas based on this new info? Or any sense of what else I should look into?

Answer 1

有多种方法可以对此进行调试。首先，将 Rack::Timeout 时间增加到 25 秒 \xe2\x80\x94 虽然这看起来会让事情变得更糟，但它将允许您准确评估请求所花费的实际时间（5.1 秒是与 25 秒不同的故事）。

\n\n

使用 NewRelic 或 Skylight 等监控工具。前者更流行，可以轻松配置为记录超过特定阈值的所有请求的跟踪。这将使您（大致）看到时间花在哪里，以及与之相关的参数/请求信息。

\n\n

如果您认为失败的请求是针对资产的，我会仔细检查您是否在生产中关闭了资产编译。你想要这个production.rb：

\n\n

# Do not fallback to assets pipeline if a precompiled asset is missed.\nconfig.assets.compile = false\n

\n\n

这意味着您需要对您提供的每项资产进行预编译。rake assets:precompile您可以通过运行并验证输出是否public/assets符合您的预期来测试您的设置是否正确。

\n\n

确保您也将日志输出到稍后可以访问的位置\xe2\x80\x94\xc2\xa0我更喜欢Papertrail，但毫无疑问还有其他。这将使您能够在错误发生时发现错误，尤其是 404（如果您请求未预编译的资产，您将看到这种错误）。一旦你隔离并解决了问题，你就可以降低这个值，但我仍然不会将其设置为低于 15 秒。

\n\n

垃圾收集是间歇性长请求时间的另一个潜在罪魁祸首，尽管 5 秒可能有点过长。较新版本的 Ruby（尤其是 2.2）可以更好地管理此问题，因此如果您可以升级正在使用的版本，可能会有所改善。

\n\n

祝你好运！

\n