Rails: Устранение неполадок в стойке::Timeout::RequestTimeoutException

Question

Получение некоторых Rack::Timeout::RequestTimeoutException: Request waited {7ms}, then ran for longer than 15000ms после обновления приложения Rails 4.2.9 до Rails 5.2.1.1.

Это поднято драгоценным камнем стойки, задокументированным здесь.

Тем не менее, у меня возникли проблемы с определением основной причины тайм-аутов. Я могу успешно загрузить URL-адреса, которые были триггерами с моей машины, но, очевидно, у других пользователей возникают проблемы.

Любая помощь в устранении неполадок будет принята с благодарностью.

Спасибо!

Backtrace (от Airbrake - включает "кодовые фрагменты"):

/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/postgresql_adapter.rb:603 in async_exec
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/postgresql_adapter.rb:603 in block (2 levels) in exec_no_cache
/gems/activesupport-5.2.1.1/lib/active_support/dependencies/interlock.rb:48 in block in permit_concurrent_loads
/gems/activesupport-5.2.1.1/lib/active_support/concurrency/share_lock.rb:187 in yield_shares
/gems/activesupport-5.2.1.1/lib/active_support/dependencies/interlock.rb:47 in permit_concurrent_loads
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/postgresql_adapter.rb:602 in block in exec_no_cache
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/abstract_adapter.rb:579 in block (2 levels) in log
vendor/ruby-2.4.4/lib/ruby/2.4.0/monitor.rb:214 in mon_synchronize
212:
    mon_enter
213:
    begin
214:
      yield
215:
    ensure
216:
      mon_exit
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/abstract_adapter.rb:578 in block in log
/gems/activesupport-5.2.1.1/lib/active_support/notifications/instrumenter.rb:23 in instrument
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/abstract_adapter.rb:569 in log
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/postgresql_adapter.rb:601 in exec_no_cache
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/postgresql_adapter.rb:590 in execute_and_clear
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:81 in exec_query
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/abstract/database_statements.rb:465 in select
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/abstract/database_statements.rb:57 in select_all
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/abstract/query_cache.rb:99 in block in select_all
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/abstract/query_cache.rb:122 in block in cache_sql
vendor/ruby-2.4.4/lib/ruby/2.4.0/monitor.rb:214 in mon_synchronize
212:
    mon_enter
213:
    begin
214:
      yield
215:
    ensure
216:
      mon_exit
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/abstract/query_cache.rb:108 in cache_sql
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/abstract/query_cache.rb:99 in select_all
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/abstract/database_statements.rb:81 in select_rows
/gems/activerecord-5.2.1.1/lib/active_record/connection_adapters/abstract/database_statements.rb:69 in select_value
/gems/activerecord-5.2.1.1/lib/active_record/relation/finder_methods.rb:322 in block in exists?
/gems/activerecord-5.2.1.1/lib/active_record/relation.rb:578 in skip_query_cache_if_necessary
/gems/activerecord-5.2.1.1/lib/active_record/relation/finder_methods.rb:322 in exists?
/gems/unread-0.10.1/lib/unread/readable.rb:124 in unread?
app/views/stories/_story.html.slim:4 in _app_views_stories__story_html_slim___4341629232572424476_47283389142580
2:
  - if story.time_capsule?
3:
    .flag = t("stories.time_capsule.label")
4:
  - elsif story.unread?(current_user)
5:
    .flag = t("stories.unread")
6:
  = link_to story_path(story), class: "open-block" do
/gems/actionview-5.2.1.1/lib/action_view/template.rb:159 in block in render
/gems/activesupport-5.2.1.1/lib/active_support/notifications.rb:168 in block in instrument
/gems/activesupport-5.2.1.1/lib/active_support/notifications/instrumenter.rb:23 in instrument
/gems/activesupport-5.2.1.1/lib/active_support/notifications.rb:168 in instrument
/gems/actionview-5.2.1.1/lib/action_view/template.rb:354 in instrument_render_template
/gems/actionview-5.2.1.1/lib/action_view/template.rb:157 in render
/gems/actionview-5.2.1.1/lib/action_view/renderer/partial_renderer.rb:344 in block in render_partial
/gems/actionview-5.2.1.1/lib/action_view/renderer/abstract_renderer.rb:44 in block in instrument
/gems/activesupport-5.2.1.1/lib/active_support/notifications.rb:168 in block in instrument
/gems/activesupport-5.2.1.1/lib/active_support/notifications/instrumenter.rb:23 in instrument
/gems/activesupport-5.2.1.1/lib/active_support/notifications.rb:168 in instrument
/gems/actionview-5.2.1.1/lib/action_view/renderer/abstract_renderer.rb:43 in instrument
/gems/actionview-5.2.1.1/lib/action_view/renderer/partial_renderer.rb:333 in render_partial
/gems/actionview-5.2.1.1/lib/action_view/renderer/partial_renderer.rb:312 in render
/gems/actionview-5.2.1.1/lib/action_view/renderer/renderer.rb:49 in render_partial
/gems/actionview-5.2.1.1/lib/action_view/helpers/rendering_helper.rb:36 in render
app/views/stories/index.html.slim:19 in block in _app_views_stories_index_html_slim___2178368229094429886_47283376767280
17:
      ul.stories.blocks
18:
        - @stories.each do |story|
19:
          = render "stories/story", story: story
20:
      = render 'comments/compact_list'
21:
    - else
app/views/stories/index.html.slim:18 in each
16:
    - if @stories.to_a.any?
17:
      ul.stories.blocks
18:
        - @stories.each do |story|
19:
          = render "stories/story", story: story
20:
      = render 'comments/compact_list'
app/views/stories/index.html.slim:18 in _app_views_stories_index_html_slim___2178368229094429886_47283376767280
16:
    - if @stories.to_a.any?
17:
      ul.stories.blocks
18:
        - @stories.each do |story|
19:
          = render "stories/story", story: story
20:
      = render 'comments/compact_list'
/gems/actionview-5.2.1.1/lib/action_view/template.rb:159 in block in render
/gems/activesupport-5.2.1.1/lib/active_support/notifications.rb:168 in block in instrument
/gems/activesupport-5.2.1.1/lib/active_support/notifications/instrumenter.rb:23 in instrument
/gems/activesupport-5.2.1.1/lib/active_support/notifications.rb:168 in instrument
/gems/actionview-5.2.1.1/lib/action_view/template.rb:354 in instrument_render_template
/gems/actionview-5.2.1.1/lib/action_view/template.rb:157 in render
/gems/actionview-5.2.1.1/lib/action_view/renderer/template_renderer.rb:54 in block (2 levels) in render_template
/gems/actionview-5.2.1.1/lib/action_view/renderer/abstract_renderer.rb:44 in block in instrument
/gems/activesupport-5.2.1.1/lib/active_support/notifications.rb:168 in block in instrument
/gems/activesupport-5.2.1.1/lib/active_support/notifications/instrumenter.rb:23 in instrument
/gems/activesupport-5.2.1.1/lib/active_support/notifications.rb:168 in instrument
/gems/actionview-5.2.1.1/lib/action_view/renderer/abstract_renderer.rb:43 in instrument
/gems/actionview-5.2.1.1/lib/action_view/renderer/template_renderer.rb:53 in block in render_template
/gems/actionview-5.2.1.1/lib/action_view/renderer/template_renderer.rb:61 in render_with_layout
/gems/actionview-5.2.1.1/lib/action_view/renderer/template_renderer.rb:52 in render_template
/gems/actionview-5.2.1.1/lib/action_view/renderer/template_renderer.rb:16 in render
/gems/actionview-5.2.1.1/lib/action_view/renderer/renderer.rb:44 in render_template
/gems/actionview-5.2.1.1/lib/action_view/renderer/renderer.rb:25 in render
/gems/actionview-5.2.1.1/lib/action_view/rendering.rb:103 in _render_template
/gems/actionpack-5.2.1.1/lib/action_controller/metal/streaming.rb:219 in _render_template
/gems/actionview-5.2.1.1/lib/action_view/rendering.rb:84 in render_to_body
/gems/actionpack-5.2.1.1/lib/action_controller/metal/rendering.rb:52 in render_to_body
/gems/actionpack-5.2.1.1/lib/action_controller/metal/renderers.rb:142 in render_to_body
/gems/actionpack-5.2.1.1/lib/abstract_controller/rendering.rb:25 in render
/gems/actionpack-5.2.1.1/lib/action_controller/metal/rendering.rb:36 in render
/gems/actionpack-5.2.1.1/lib/action_controller/metal/instrumentation.rb:46 in block (2 levels) in render
/gems/activesupport-5.2.1.1/lib/active_support/core_ext/benchmark.rb:14 in block in ms
vendor/ruby-2.4.4/lib/ruby/2.4.0/benchmark.rb:308 in realtime
306:
  def realtime # :yield:
307:
    r0 = Process.clock_gettime(Process::CLOCK_MONOTONIC)
308:
    yield
309:
    Process.clock_gettime(Process::CLOCK_MONOTONIC) - r0
310:
  end
/gems/activesupport-5.2.1.1/lib/active_support/core_ext/benchmark.rb:14 in ms
/gems/actionpack-5.2.1.1/lib/action_controller/metal/instrumentation.rb:46 in block in render

Answer 1

если это поможет, я решил проблему, запустив

      export RACK_TIMEOUT_SERVICE_TIMEOUT=30

в терминале.

Answer 2

У меня очень похожая проблема. 30-е годы в моем случае. Мне сказали, что это жесткий предел для Heroku. но теперь, когда у вас 15-секундный тайм-аут, есть кое-что еще. Может, за последние 9 месяцев увеличили? (маловероятно), а может, это зависит от плана. или, может быть, это не имеет ничего общего с Heroku, и этоrack-timeout драгоценный камень делает это.

согласно их README. вы можете обновитьRACK_TIMEOUT_SERVICE_TIMEOUT переменная среды на что-то большее

или удалите драгоценный камень, если вам не нужны производственные ошибки, чтобы сообщить о медленных конечных точках... вздох

И у меня этот var уже установлен на 30 секунд

Я увеличил его до 60, я дам вам знать через несколько дней, если это исправит

https://github.com/sharpstone/rack-timeout

Обновление: этот драгоценный камень убивает запрос раньше времени, но также существует ограничение на героку. если вы отключите этот драгоценный камень, вы увидите, что H12 возвращает heroku в ваших журналах или на экране показателей.

См. Эту статью для получения более подробной информации об их жестком лимите.

https://devcenter.heroku.com/articles/limits

Answer 3

Привет, ребята, я решил эту проблему удалением gem 'rack-timeout' и беги rails server.