ALB转发请求后Puma延迟8-10秒处理的排查与监控问题

我有一个常规的Ruby on Rails应用，使用Puma服务器运行，配置为-w 1 -t 1:1（即1个工作进程、1个线程）。该应用部署在EC2实例上，前端由AWS ALB提供服务，架构如下：

近期发现特定时间点部分请求出现延迟：

• ALB日志显示多个请求的Target Processing Time超过8-10秒，但对应请求在Rails日志中的处理耗时仅数毫秒
• Rails日志中Started行的时间戳比ALB日志的请求接收时间晚8-10秒
• ALB日志显示请求转发至目标仅耗时约1毫秒，排除ALB滞留可能
• ALB连接超时设为10秒，这类延迟请求未被标记为Error，说明EC2实例已在时限内接受TCP连接

推测请求在OS层或Puma主进程层排队等待8-10秒后，才被交给工作进程处理。

技术问题 #

1. 请求卡在了哪个环节？该如何定位排查？
2. 如何确定导致延迟的具体原因？
3. 是否有可监控的指标用于此类延迟场景的告警？

1. 请求卡顿环节定位与排查步骤 #

确认卡顿环节 #

根据现象，请求已通过ALB到达EC2并完成TCP握手，但Rails开始处理的时间大幅滞后，卡顿环节锁定在EC2实例的OS网络栈到Puma工作进程接收请求之间，可能的位置包括：

• OS的TCP连接队列（backlog）
• Puma主进程的连接接收队列
• Puma工作进程被阻塞，无法及时处理新连接

排查步骤 #

• 检查OS TCP连接状态：
  • 执行netstat -anp | grep <puma-port>或ss -tulpn | grep <puma-port>，查看处于SYN_RECV、ESTABLISHED状态的连接数，若SYN_RECV过多，说明OS的TCP backlog已满，新连接被排队
  • 查看/proc/sys/net/core/somaxconn和Puma配置的backlog参数（默认1024），确认是否存在配置不匹配
• 分析Puma进程状态：
  • 执行ps aux | grep puma，确认主进程和工作进程是否存活，有无僵死情况
  • 使用puma status（若配置了控制端口）查看工作进程的繁忙状态，是否长期处于busy
  • 开启Puma的debug日志，查看主进程接收连接后转发给工作进程的时间差
• 跟踪请求链路：
  • 使用tcpdump在EC2实例上抓包，过滤目标端口的流量，对比TCP握手完成时间与Rails日志Started时间，确认延迟发生在TCP握手后到Rails处理前
  • 借助strace跟踪Puma主进程和工作进程的系统调用，查看是否有阻塞在accept()、read()等调用上的情况

2. 延迟具体原因定位 #

常见原因及验证方式 #

• Puma资源不足：
  当前配置是1进程1线程，若此时有一个长耗时请求（比如慢查询、外部API调用），工作进程会被完全占用，后续请求只能在Puma队列中等待。验证：查看Rails日志中延迟请求的前序请求是否有耗时较长的操作
• OS资源瓶颈：
  • CPU：使用top或htop查看EC2实例的CPU使用率，若CPU长期100%，Puma进程可能无法及时调度
  • 内存：若内存不足导致swap频繁使用（vmstat查看si/so列），进程调度会出现延迟
  • 文件描述符：检查ulimit -n和Puma打开的文件描述符数（lsof -p <puma-pid> | wc -l），若超过限制，新连接无法被处理
• Puma主进程阻塞：
  Puma主进程负责接收连接并转发给工作进程，若主进程被阻塞（比如执行同步IO、GC停顿过长），会导致连接无法及时转发。验证：查看Puma主进程的CPU/内存占用，结合strace看是否有长时间阻塞的系统调用
• 网络层面隐性问题：
  比如EC2实例的网络带宽被占满（iftop查看），导致请求数据传输延迟；或者安全组/网络ACL的规则导致隐性延迟（虽然TCP握手已完成，但数据传输受阻）

3. 可监控的告警指标 #

OS层面指标 #

• TCP连接队列长度：监控net.core.somaxconn与实际队列使用量的差值，当队列使用率超过80%时告警
• CPU使用率：设置阈值（比如持续5分钟超过90%）告警
• 内存使用率：当可用内存低于20%或swap使用率超过50%时告警
• 文件描述符使用率：当进程打开的文件描述符超过限制的80%时告警

Puma层面指标 #

• Puma工作进程繁忙率：通过Puma的监控API（配置bind "tcp://0.0.0.0:9293"开启）获取worker_busy指标，当繁忙率持续100%超过1分钟时告警
• 请求排队时间：自定义中间件，记录请求到达Rails的时间与ALB请求时间的差值，当差值超过2秒时告警
• Puma进程存活状态：监控主进程和工作进程的PID，若进程消失或无响应时告警

AWS层面指标 #

• ALB的TargetResponseTime：虽然当前现象是Rails处理时间短，但TargetResponseTime包含排队时间，可设置阈值（比如超过5秒）告警
• EC2实例的CPUUtilization、MemoryUtilization、NetworkIn/Out：通过CloudWatch设置告警阈值

内容的提问来源于stack exchange，提问作者brahmana