在 Heroku 从 Unicorn 切换到 Puma 时的 H12

Question

按照 Heroku 的建议，我将我们的一个 Rails 3.2 (/Ruby 2.0.0) 应用程序从 Unicorn 切换到了 Puma。几乎立即，我们开始在至少 5% 的请求中看到许多 30 秒超时（H12 错误）。我们在 Unicorn 上运行时从未有过的东西。

这是我们的设置：

workers Integer(ENV['WEB_CONCURRENCY'] || 2)
threads_count = Integer(ENV['MAX_THREADS'] || 5)
threads threads_count, threads_count

preload_app!

rackup      DefaultRackup
port        ENV['PORT'] || 3443
environment ENV['RACK_ENV']     || 'development'

on_worker_boot do
  # Valid on Rails up to 4.1 the initializer method of setting `pool` size
  ActiveSupport.on_load(:active_record) do
    config = ActiveRecord::Base.configurations[Rails.env] || Rails.application.config.database_configuration[Rails.env]
    config['pool'] = ENV['DB_POOL'] || ENV['MAX_THREADS'] || 5
    ActiveRecord::Base.establish_connection(config)
  end
end

由于我们的应用可能不是线程安全的，因此我们将MAX_THREADS 设置为1，并通过将WEB_CONCURRENCY 设置为从4 到8 的值来扩展进程。我们通常运行一些 2x dynos，但我们也尝试了 1x dynos。无论我们如何放大或缩小这些，H12 都会不断出现。内存使用量保持在正常范围内。此外，由于每个进程只运行 1 个线程，我们将 DB_POOL 设置为 1。我们还将 Rack::Timeout 配置为在 28 秒时超时。

我一直在努力寻找造成这种情况的原因。有没有人知道可能出了什么问题或者如何最容易地找到导致这种情况的原因？

谢谢！

附：我们想要远离 Unicorn 的主要原因是，我们往往会有一些偶尔出现的慢客户端，它们会阻塞整个请求事务数组。 Puma 大概不会因此受到影响，所以我们真的很想继续这样做。

Answer 1

（对不起，这里没有答案，但希望这会演变成一个！）

我也在努力解决这个问题。我已经确定的一件事是，对于 99% 的 H12 请求，我没有来自 Rails 本身的单个日志条目——仅来自 heroku[router]。 （1% 的日志行来自以下一项或多项：Rack-Timeout 中间件、Rails 本身或我自己在 before_filter 中的日志记录）

我通过将 Rails 配置为在每个日志行中记录 request-id（顺便说一下，worker 的 PID）来确定这一点，然后编写了一个 quick-n-dirty shell 脚本来搜索日志文件。 （我设置了我自己的 syslogd logdrain，它将日志保存到一个名为“heroku”的文件中）

添加到config/application.rb

## Log the X-Request-ID HTTP request header, provided by Heroku's load-balancer
## (or created by Rails itself, in its absence, e.g. on dev)
## Rails exposes this value as `request.uuid`.
## log_tags[] calls `request.send(symbol)` and adds "[value] " to the start of each logged line.
## See https://devcenter.heroku.com/articles/http-request-id
config.log_tags = [ :uuid ]
config.log_tags << proc { "PID:#{$$}" }

日志解析脚本：

cat heroku | 
    grep code=H12 | 
    perl -pe 's/^.*request_id=([^ ]*).*/$1/' | 
    while read id ; do
        echo -n "$id: "
        cat heroku |
            grep $id | 
            wc -l
    done

或一行：

cat heroku | grep code=H12 | perl -pe 's/^.*request_id=([^ ]*).*/$1/' | while read id ; do echo -n "$id: " ; cat heroku | grep $id | wc -l ; done