Puma 网络服务器积压行为
Puma web server backlog behavior
这是在 Heroku 上，但截至目前我认为它与此没有具体关系。我们还使用 rack-timeout gem，它应该在 30 秒后终止进程。请在下面查看为什么在某些情况下看起来没有发生这种情况。
我们有一个非常大的 puma 池 workers/threads，5 个 worker，每个 worker 有 20 个线程。在提到这个问题时，我们有 5 个 heroku dynos 运行，因此总共有 500 个 puma 实例可用于工作请求。有了这么多，我很难相信一些长 运行 请求会导致如此多的 503。
我设置了 Puma 指标并将它们添加到自定义日志记录线程，这是一个快照示例，我们从这个上午开始在 503 秒内出现上升，其中 Puma 积压结果很奇怪：
Oct 24 09:06:56 app app[web] info "source=web.1.worker.28 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:06:56 app app[web] info "source=web.1.worker.54 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:06:56 app app[web] info "source=web.1.worker.72 sample#puma.backlog=99 sample#puma.running=20"
Oct 24 09:06:56 app app[web] info "source=web.1.worker.90 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:06:57 app app[web] info "source=web.3.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:06:57 app app[web] info "source=web.3.worker.29 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:06:57 app app[web] info "source=web.3.worker.40 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:06:57 app app[web] info "source=web.3.worker.51 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:06:57 app app[web] info "source=web.3.worker.62 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.4.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.4.worker.29 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.4.worker.40 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.4.worker.51 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.4.worker.62 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.2.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.2.worker.34 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.2.worker.50 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.2.worker.66 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.2.worker.82 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:05 app app[web] info "source=web.5.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:05 app app[web] info "source=web.5.worker.29 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:05 app app[web] info "source=web.5.worker.47 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:05 app app[web] info "source=web.5.worker.69 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:05 app app[web] info "source=web.5.worker.74 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:06 app app[web] info "source=web.1.worker.18 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:06 app app[web] info "source=web.1.worker.28 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:06 app app[web] info "source=web.1.worker.54 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:06 app app[web] info "source=web.1.worker.72 sample#puma.backlog=99 sample#puma.running=20"
Oct 24 09:07:06 app app[web] info "source=web.1.worker.90 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:07 app app[web] info "source=web.3.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:07 app app[web] info "source=web.3.worker.29 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:07 app app[web] info "source=web.3.worker.40 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:07 app app[web] info "source=web.3.worker.51 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:07 app app[web] info "source=web.3.worker.62 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.2.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.2.worker.34 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.2.worker.50 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.2.worker.66 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.2.worker.82 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.4.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.4.worker.29 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.4.worker.40 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.4.worker.51 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.4.worker.62 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:15 app app[web] info "source=web.5.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:15 app app[web] info "source=web.5.worker.29 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:15 app app[web] info "source=web.5.worker.47 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:15 app app[web] info "source=web.5.worker.69 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:15 app app[web] info "source=web.5.worker.74 sample#puma.backlog=0 sample#puma.running=20"
如果一个工人（例如 web.1.worker.72）有 >=1 的积压，为什么 puma 向它提出更多请求，而你可以看到我们有其他工人没有积压？
为什么这种情况会持续几分钟（完整日志显示 dyno 1 上的工作人员 72 的积压工作超过 3 分钟 >99）：
web.1.worker.72 sample#puma.backlog=99
注意情况变得更糟：
Oct 24 09:08:26 app app[web] info "source=web.1.worker.72 sample#puma.backlog=153 sample#puma.running=20"
然后终于更好了：
Oct 24 09:08:36 app app[web] info "source=web.1.worker.72 sample#puma.backlog=68 sample#puma.running=20"
然后恢复健康：
Oct 24 09:08:46 app app[web] info "source=web.1.worker.72 sample#puma.backlog=0 sample#puma.running=20"
503s 在 9:08am 停止，我们恢复了健康，所以这肯定与持续数分钟的奇怪积压事件有关。有人有什么想法吗？
似乎缩放根本没有帮助...
在与几个人交谈后，事实证明这是 puma 中的一个错误，已在 3.12 版中修复（我们在 3.11 上第一次写这个问题时）。升级到 4.2 后，我可以确认它按预期工作。
这是在 Heroku 上，但截至目前我认为它与此没有具体关系。我们还使用 rack-timeout gem，它应该在 30 秒后终止进程。请在下面查看为什么在某些情况下看起来没有发生这种情况。
我们有一个非常大的 puma 池 workers/threads，5 个 worker，每个 worker 有 20 个线程。在提到这个问题时，我们有 5 个 heroku dynos 运行，因此总共有 500 个 puma 实例可用于工作请求。有了这么多，我很难相信一些长 运行 请求会导致如此多的 503。
我设置了 Puma 指标并将它们添加到自定义日志记录线程，这是一个快照示例，我们从这个上午开始在 503 秒内出现上升，其中 Puma 积压结果很奇怪：
Oct 24 09:06:56 app app[web] info "source=web.1.worker.28 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:06:56 app app[web] info "source=web.1.worker.54 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:06:56 app app[web] info "source=web.1.worker.72 sample#puma.backlog=99 sample#puma.running=20"
Oct 24 09:06:56 app app[web] info "source=web.1.worker.90 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:06:57 app app[web] info "source=web.3.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:06:57 app app[web] info "source=web.3.worker.29 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:06:57 app app[web] info "source=web.3.worker.40 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:06:57 app app[web] info "source=web.3.worker.51 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:06:57 app app[web] info "source=web.3.worker.62 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.4.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.4.worker.29 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.4.worker.40 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.4.worker.51 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.4.worker.62 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.2.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.2.worker.34 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.2.worker.50 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.2.worker.66 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:01 app app[web] info "source=web.2.worker.82 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:05 app app[web] info "source=web.5.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:05 app app[web] info "source=web.5.worker.29 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:05 app app[web] info "source=web.5.worker.47 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:05 app app[web] info "source=web.5.worker.69 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:05 app app[web] info "source=web.5.worker.74 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:06 app app[web] info "source=web.1.worker.18 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:06 app app[web] info "source=web.1.worker.28 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:06 app app[web] info "source=web.1.worker.54 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:06 app app[web] info "source=web.1.worker.72 sample#puma.backlog=99 sample#puma.running=20"
Oct 24 09:07:06 app app[web] info "source=web.1.worker.90 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:07 app app[web] info "source=web.3.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:07 app app[web] info "source=web.3.worker.29 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:07 app app[web] info "source=web.3.worker.40 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:07 app app[web] info "source=web.3.worker.51 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:07 app app[web] info "source=web.3.worker.62 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.2.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.2.worker.34 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.2.worker.50 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.2.worker.66 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.2.worker.82 sample#puma.backlog=1 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.4.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.4.worker.29 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.4.worker.40 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.4.worker.51 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:11 app app[web] info "source=web.4.worker.62 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:15 app app[web] info "source=web.5.worker.18 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:15 app app[web] info "source=web.5.worker.29 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:15 app app[web] info "source=web.5.worker.47 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:15 app app[web] info "source=web.5.worker.69 sample#puma.backlog=0 sample#puma.running=20"
Oct 24 09:07:15 app app[web] info "source=web.5.worker.74 sample#puma.backlog=0 sample#puma.running=20"
如果一个工人（例如 web.1.worker.72）有 >=1 的积压，为什么 puma 向它提出更多请求，而你可以看到我们有其他工人没有积压？
为什么这种情况会持续几分钟（完整日志显示 dyno 1 上的工作人员 72 的积压工作超过 3 分钟 >99）：
web.1.worker.72 sample#puma.backlog=99
注意情况变得更糟：
Oct 24 09:08:26 app app[web] info "source=web.1.worker.72 sample#puma.backlog=153 sample#puma.running=20"
然后终于更好了：
Oct 24 09:08:36 app app[web] info "source=web.1.worker.72 sample#puma.backlog=68 sample#puma.running=20"
然后恢复健康：
Oct 24 09:08:46 app app[web] info "source=web.1.worker.72 sample#puma.backlog=0 sample#puma.running=20"
503s 在 9:08am 停止，我们恢复了健康，所以这肯定与持续数分钟的奇怪积压事件有关。有人有什么想法吗？
似乎缩放根本没有帮助...
在与几个人交谈后，事实证明这是 puma 中的一个错误，已在 3.12 版中修复（我们在 3.11 上第一次写这个问题时）。升级到 4.2 后，我可以确认它按预期工作。