Rails4で何故かレンダリングに時間がかかりすぎタイムアウトしてしまう。

Question

Ruby on Rails4.2.5 で開発をしているのですが、突然localhostにアクセスしてもタイムアウトしてしまうようになってしまいました。ログを見てみるとデータベスの接続やキャッシュとかは何msなのですが、レンダリングに異常なほど時間がかかっていて、それでタイムアウトしてしまいます。

今までは正常なレスポンスタイムで描画していたのですが、突然このようにタイムアウトしてしまうほど時間がかかってしまった原因がわかりません。わかる方いましたらご教授お願いします。

####環境

• unciron 5.0.1
• rails 4.2.5
• ruby 2.2.3
• slim 3.0.6
• slim-rails 3.0.1

source=rack-timeout id=af394e65fcb94164bd551f8e325d478f timeout=25000ms service=33170ms state=active
source=rack-timeout id=af394e65fcb94164bd551f8e325d478f timeout=25000ms service=33216ms state=timed_out
  Rendered evideos/show.html.slim within layouts/full (33171.4ms)
Completed 500 Internal Server Error in 33207ms (ActiveRecord: 3.3ms)

Rack::Timeout::RequestTimeoutException - Request ran for longer than 25000ms:
  sprockets (3.5.2) lib/sprockets/cache/file_store.rb:101:in `set'
  sprockets (3.5.2) lib/sprockets/cache.rb:210:in `set'
  sprockets (3.5.2) lib/sprockets/cache.rb:136:in `set'
  sprockets (3.5.2) lib/sprockets/loader.rb:244:in `store_asset'
  ...
  sprockets-rails (3.0.4) lib/sprockets/rails/helper.rb:229:in `block in resolve_asset'
  sprockets-rails (3.0.4) lib/sprockets/rails/helper.rb:228:in `resolve_asset'
  sprockets-rails (3.0.4) lib/sprockets/rails/helper.rb:215:in `lookup_debug_asset'
  sprockets-rails (3.0.4) lib/sprockets/rails/helper.rb:128:in `block in javascript_include_tag'
  sprockets-rails (3.0.4) lib/sprockets/rails/helper.rb:127:in `javascript_include_tag'
  app/views/evideos/show.html.slim:7:in `block in _app_views_evideos_show_html_slim___135235524447124923_70234700341860'
  actionview (4.2.5) lib/action_view/helpers/capture_helper.rb:38:in `block in capture'
  actionview (4.2.5) lib/action_view/helpers/capture_helper.rb:202:in `with_output_buffer'
  actionview (4.2.5) lib/action_view/helpers/capture_helper.rb:38:in `capture'
  actionview (4.2.5) lib/action_view/helpers/capture_helper.rb:152:in `content_for'
  app/views/evideos/show.html.slim:6:in `_app_views_evideos_show_html_slim___135235524447124923_70234700341860'
  actionview (4.2.5) lib/action_view/template.rb:145:in `block in render'
  activesupport (4.2.5) lib/active_support/notifications.rb:166:in `instrument'
  actionview (4.2.5) lib/action_view/template.rb:333:in `instrument'
  actionview (4.2.5) lib/action_view/template.rb:143:in `render'
  actionview (4.2.5) lib/action_view/rendering.rb:83:in `render_to_body'
  activesupport (4.2.5) lib/active_support/core_ext/benchmark.rb:12:in `block in ms'
  actionpack (4.2.5) lib/action_controller/metal/instrumentation.rb:43:in `render'
  meta-tags (2.1.0) lib/meta_tags/controller_helper.rb:26:in `render_with_meta_tags'
  app/controllers/evideos_controller.rb:77:in `show'
  ...
  actionpack (4.2.5) lib/action_dispatch/middleware/params_parser.rb:27:in `call'
  actionpack (4.2.5) lib/action_dispatch/middleware/flash.rb:260:in `call'
  rack (1.6.4) lib/rack/session/abstract/id.rb:225:in `context'
  rack (1.6.4) lib/rack/session/abstract/id.rb:220:in `call'
  actionpack (4.2.5) lib/action_dispatch/middleware/cookies.rb:560:in `call'
  activerecord (4.2.5) lib/active_record/query_cache.rb:36:in `call'
  activerecord (4.2.5) lib/active_record/connection_adapters/abstract/connection_pool.rb:653:in `call'
  activerecord (4.2.5) lib/active_record/migration.rb:377:in `call'
  actionpack (4.2.5) lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
  activesupport (4.2.5) lib/active_support/callbacks.rb:88:in `__run_callbacks__'
  activesupport (4.2.5) lib/active_support/callbacks.rb:778:in `_run_call_callbacks'
  activesupport (4.2.5) lib/active_support/callbacks.rb:81:in `run_callbacks'
  actionpack (4.2.5) lib/action_dispatch/middleware/callbacks.rb:27:in `call'
  actionpack (4.2.5) lib/action_dispatch/middleware/reloader.rb:73:in `call'
  actionpack (4.2.5) lib/action_dispatch/middleware/remote_ip.rb:78: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 (4.2.5) lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'
  web-console (3.1.1) lib/web_console/middleware.rb:131:in `call_app'
  web-console (3.1.1) lib/web_console/middleware.rb:28:in `block in call'
  web-console (3.1.1) lib/web_console/middleware.rb:18:in `call'
  actionpack (4.2.5) lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
  railties (4.2.5) lib/rails/rack/logger.rb:38:in `call_app'
  railties (4.2.5) lib/rails/rack/logger.rb:22:in `call'
  quiet_assets (1.1.0) lib/quiet_assets.rb:27:in `call_with_quiet_assets'
  request_store (1.3.0) lib/request_store/middleware.rb:9:in `call'
  actionpack (4.2.5) lib/action_dispatch/middleware/request_id.rb:21:in `call'
  rack (1.6.4) lib/rack/methodoverride.rb:22:in `call'
  rack (1.6.4) lib/rack/runtime.rb:18:in `call'
  rack-timeout (0.3.2) lib/rack/timeout/core.rb:125:in `block in call'
  rack-timeout (0.3.2) lib/rack/timeout/support/timeout.rb:19:in `timeout'
  rack-timeout (0.3.2) lib/rack/timeout/core.rb:124:in `call'
  activesupport (4.2.5) lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
  rack (1.6.4) lib/rack/lock.rb:17:in `call'
  actionpack (4.2.5) lib/action_dispatch/middleware/static.rb:116:in `call'
  rack (1.6.4) lib/rack/sendfile.rb:113:in `call'
  rack-mini-profiler (0.9.8) lib/mini_profiler/profiler.rb:282:in `call'
  railties (4.2.5) lib/rails/engine.rb:518:in `call'
  railties (4.2.5) lib/rails/application.rb:165:in `call'
  rack-cors (0.3.0) lib/rack/cors.rb:72:in `call'
  rack (1.6.4) lib/rack/lock.rb:17:in `call'
  rack (1.6.4) lib/rack/content_length.rb:15:in `call'
  rack (1.6.4) lib/rack/handler/webrick.rb:88:in `service'
  /Users/sakaihidenobu/.rbenv/versions/2.2.3/lib/ruby/2.2.0/webrick/httpserver.rb:138:in `service'
  /Users/sakaihidenobu/.rbenv/versions/2.2.3/lib/ruby/2.2.0/webrick/httpserver.rb:94:in `run'
  /Users/sakaihidenobu/.rbenv/versions/2.2.3/lib/ruby/2.2.0/webrick/server.rb:294:in `block in start_thread'

source=rack-timeout id=af394e65fcb94164bd551f8e325d478f timeout=25000ms service=33298ms state=completed
source=rack-timeout id=41ede62d2caf4d887d50593db080aa6a timeout=25000ms state=ready
source=rack-timeout id=41ede62d2caf4d887d50593db080aa6a timeout=25000ms service=0ms state=active

source=rack-timeout id=41ede62d2caf4d887d50593db080aa6a timeout=25000ms service=156ms state=completed

また、今回のレンダリングにとてつもなく時間をかけているレイアウトです。

doctype html
head
  = include_gon
  = stylesheet_link_tag    "application", media: "all", :debug => true
  = javascript_include_tag "application", :debug => true
  = csrf_meta_tags
  - if content_for(:page_title)
    - set_meta_tags site: 'aaaaaa', title: yield(:page_title), reverse: true
  - else
    - set_meta_tags site: 'aaaaaa'
  = display_meta_tags default_meta_tags
  = favicon_link_tag('favicon.ico')
  == yield :head
  = analytics_init if Rails.env.production?
.wrap
  body class="#{controller_name} #{action_name}"
  #fb-root
  javascript:
    (function(d, s, id) { var js, fjs = d.getElementsByTagName(s)[0]; if (d.getElementById(id)) return; js = d.createElement(s); js.id = id; js.async = true; js.src = "//connect.facebook.net/ja_JP/sdk.js#xfbml=1&version=v2.5&appId=1830645683829206"; fjs.parentNode.insertBefore(js, fjs); }(document, 'script', 'facebook-jssdk'));
  #loading
    = image_tag "loading.gif", size: '43x11', alt: 'loading...'
  .countatiner-fluid
    .row
      .col-sm-12.col-md-12 style="padding:0;margin:0"
        header.clearfix
          == render 'templates/header'
          == render 'templates/category'
          == yield :header
      .col-sm-12.col-md-12.col-lg-offset-1.col-lg-10
        = alert_or_notice alert, notice
        aritlce.main
          == yield
      .col-sm-12.col-md-12
        footer
          == render 'templates/footer'
  #pagetop.pagetop
    i.glyphicon.glyphicon-chevron-up

Answer 1

######config/environment/development.rb

  config.assets.compress = true
  config.assets.js_compressor = :uglifier
  config.assets.css_compressor = :sass
  config.assets.debug = true

としていたが、開発環境では1リクエストごとに動的にコンパイルしているらしいので、これが原因でページ遷移するたびに異常に時間がかかっていた。
この設定の

  config.assets.debug = false

に変更することで、最初のリクエスト時にassetsをキャッシュして、それ以後はキャッシュしたjsとcssを使うようになったので、正常なレスポンスタイムに戻りました。

参考

Rails3?のassets precompileの日本語訳
やっぱりassets precompileとかもしっかりと理解しないといけないなと改めて実感しました。