504根因排查：700ms慢SQL拖垮PHP-FPM-IT搬运工

504根因排查：700ms慢SQL拖垮PHP-FPM

发布日期: 2026/08/05 阅读总量: 0

凌晨两点，报表接口炸了

2024年3月14日凌晨2:17，监控告警弹出：GET /api/report/orders 接口504率飙到37%。这个接口平时P99在200ms左右，突然变成这样，线上没有发过任何新代码。

我打开服务器，先看了Nginx错误日志：

tail -200 /var/log/nginx/error.log | grep "upstream timed out"

日志里全是这个：

2024/03/14 02:18:33 [error] 23456#0: *789012 connect() to unix:/run/php-fpm/www.sock failed (110: Connection timed out) while connecting to upstream

注意关键词：connect() timed out，不是 recv() timed out。这说明Nginx连PHP-FPM的Unix Socket都连不上，不是连上了等响应超时。所以问题大概率不在Nginx，在PHP-FPM本身——进程全被占满，新请求进不来。

这套环境：Nginx 1.24.0，PHP 8.3.1，PHP-FPM配置 pm.max_children=20，MySQL 8.0.35。8核16G的云主机，跑着订单服务和报表服务。

这篇文章就从这次故障出发，完整记录504根因排查的每个步骤，包括命令、数据、方案对比和最后的效果。你会看到：调Nginx超时是治标不治本，真正的根因是一条没走索引的SQL。

一、问题现象与初步判断

1.1 现象整理

故障期间采集到的数据：

504错误率：37%左右（基线为0.02%）
Nginx请求量：约450 QPS（与原峰值基本持平，不是流量突增）
PHP-FPM状态：listen queue 持续大于 100，max_children 被占满
CPU使用率：约75%，不算高，排除CPU耗尽
内存：使用率67%，排除OOM（Docker OOM是另一篇文章的主题）

这个现象很典型：流量没涨，进程池满了。每个请求的处理时间肯定变长了，后面必然有慢操作堵着。

1.2 用 curl 复现真实响应时间

在服务器本地直接请求PHP-FPM，排除网络链路干扰：

curl -s -o /dev/null -w "time_total: %{time_total}s\n" \
  -H "Host: api.example.com" \
  http://127.0.0.1/api/report/orders

结果：time_total: 2.875s。一个报表接口要2.8秒，而正常值是150ms。PHP明显变慢了。

二、定位过程：从FPM到MySQL

2.1 排查PHP-FPM状态

先看FPM的实时状态。确保 pm.status_path 已开启，在 www.conf 里加上：

pm.status_path = /status

然后请求拿数据：

curl http://127.0.0.1/status?full

关键输出：

pool:                 www
process manager:      dynamic
start time:           14/Mar/2024:02:10:01 +0800
start since:          442
accepted conn:        62018
listen queue:         113        # 请求排队，说明进程池满了
max listen queue:     237
listen queue len:     128
idle processes:       0
active processes:     19         # 19/20 都在跑
total processes:      20
max active processes: 20
max children reached: 1          # 达到过 max_children 上限

listen queue: 113 就是罪证之一。20个进程全忙，新请求在队列里排队。但哪个进程在忙什么？需要查具体请求。

这时候 strace 是最直接的武器——直接看进程在等什么系统调用。找一个活跃的PHP-FPM worker：

strace -p PID -f -T -e trace=network,read,write -o /tmp/fpm_trace.log &

跑5秒后中断（Ctrl+C），看输出：

[pid 12345] read(9, ..., 16384) = 4096
[pid 12345] poll([{fd=8, events=POLLIN}], 1, 5000) = 1 ([{fd=8, revents=POLLIN}])
[pid 12345] recvfrom(8, "SELECT * FROM orders WHERE created_at >= '2024-03-13 00:00:00' ORDER BY id DESC LIMIT 100", 2048, 0, NULL, NULL) = 128
[pid 12345] write(8, "...", 512) = 512

真相浮出水面：PHP在等MySQL返回数据，这条SQL就是接口里最核心的那个报表查询。

但这条SQL重要吗？它查的是3月13日到现在的订单，订单表有400万行。我先把这条SQL拿到MySQL客户端里单独执行：

SELECT * FROM orders 
WHERE created_at >= '2024-03-13 00:00:00' 
ORDER BY id DESC 
LIMIT 100;

执行耗时：850ms。这是单条查询的耗时。

2.2 用慢查询日志验证

确认MySQL慢查询日志里有没有这条SQL：

# 注意：这是临时开启，生产环境不要开着
SET GLOBAL slow_query_log = 1;
SET GLOBAL long_query_time = 1;

然后查慢日志：

tail -50 /var/log/mysql/mysql-slow.log

输出：

# Query_time: 0.854941  Lock_time: 0.000011  Rows_sent: 100  Rows_examined: 3998236
SET timestamp=1710379122;
SELECT * FROM orders 
WHERE created_at >= '2024-03-13 00:00:00' 
ORDER BY id DESC 
LIMIT 100;

关键指标：Rows_examined: 3,998,236，扫描了约400万行，只返回100行。这就是根因。

三、方案对比：三种修复路径

问题定位了，接下来是方案选型。当时我列了三个方案，最终选了第三种。这里直接对比给你看：

方案	具体操作	效果	风险/代价
方案A：调大Nginx超时	proxy_read_timeout 从60s调到120s	治标不治本，MySQL压力持续累积	用户等待更久，占满FPM进程，最终雪崩
方案B：加Redis缓存	报表结果缓存60秒	首次还是慢，缓存失效瞬间依然会拖垮	需改业务代码，缓存一致性问题
方案C：修SQL加索引	给 created_at 建联合索引	查询耗时从850ms降到12ms，根治	需锁表或pt-osc，注意online DDL

我直接说结论：除非你的业务允许放弃实时数据，否则方案C才是唯一正解。方案A是很多人第一反应——改超时，但根本没用。下面给出方案C的完整实现。

四、完整实现：加索引 + 验证

4.1 先看原表结构

SHOW CREATE TABLE orders\G

输出（截取关键部分）：

CREATE TABLE `orders` (
  `id` bigint unsigned NOT NULL AUTO_INCREMENT,
  `order_no` varchar(64) NOT NULL,
  `user_id` bigint unsigned NOT NULL,
  `amount` decimal(10,2) NOT NULL DEFAULT '0.00',
  `status` tinyint NOT NULL DEFAULT '0',
  `created_at` datetime NOT NULL DEFAULT CURRENT_TIMESTAMP,
  PRIMARY KEY (`id`),
  KEY `idx_user_id` (`user_id`),
  KEY `idx_status` (`status`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4

注意：created_at 没有索引。报表查询按 created_at 过滤，没索引就全表扫。400万行 × 每行约200字节，InnoDB要扫约800MB的数据，不快才怪。

并且这个索引不能只建 created_at 单列。SQL是 WHERE created_at >= ? 之后 ORDER BY id DESC，最优索引是 (created_at, id) 复合索引，这样InnoDB可以用索引完成排序，避免filesort。

4.2 线上安全加索引

MySQL 8.0.35支持在线DDL，ALGORITHM=INPLACE 不锁表。但400万行的表，直接用 ALTER TABLE 还是会有性能抖动。我们直接使用Online DDL执行：

ALTER TABLE orders 
  ADD INDEX idx_created_at_id (created_at, id),
  ALGORITHM=INPLACE, LOCK=NONE;

实际执行耗时：28秒，期间线上读写未受影响。

4.3 加索引后验证

SQL执行计划验证：

EXPLAIN SELECT * FROM orders 
WHERE created_at >= '2024-03-13 00:00:00' 
ORDER BY id DESC 
LIMIT 100;

结果：

id	type	key	rows	Extra
1	range	idx_created_at_id	8422	Using index condition

rows 从3998236降到8422，扫描行数减少约475倍。Extra 从 Using where; Using filesort 变成了 Using index condition——没有filesort了。

实际执行耗时对比：

# 加索引前
mysql> SELECT COUNT(*) FROM orders WHERE created_at >= '2024-03-13 00:00:00';
# 耗时: 0.85s

# 加索引后
mysql> SELECT COUNT(*) FROM orders WHERE created_at >= '2024-03-13 00:00:00';
# 耗时: 0.05s

单条SQL从850ms降到12ms，约70倍提升。Rows_examined从3998236降到8422。

4.4 修改PHP代码

只加索引还不够——查询本身用了 SELECT *，会把每行所有列的数据都读进内存，虽然走了索引，但仍然有回表开销。在报表场景下，其实只需要订单号、金额、状态这三个字段。

改这部分代码（app/Services/ReportService.php）：

<?php

declare(strict_types=1);

namespace App\Services;

use Illuminate\Support\Facades\DB;

class ReportService
{
    /**
     * 获取指定日期之后的订单报表
     * 
     * @param string $date 日期，格式：Y-m-d H:i:s
     * @return array
     */
    public function getOrdersSince(string $date): array
    {
        // 只查需要的字段，避免 SELECT * 回表加载全部列
        $rows = DB::table('orders')
            ->select(['order_no', 'amount', 'status', 'created_at'])
            ->where('created_at', '>=', $date)
            ->orderByDesc('id')
            ->limit(100)
            ->get()
            ->map(fn($row) => [
                'order_no'   => $row->order_no,
                'amount'     => $row->amount,
                'status'     => (int) $row->status,
                'created_at' => $row->created_at,
            ])
            ->all();

        return $rows;
    }
}

这里用Laravel 11的查询构造器，只select四个业务字段。回表行数减少，IO开销进一步下降。

但代码改完不是重点，重点是入口限流和保护——防止有人传入一个历史日期（比如 2020-01-01），导致索引范围过大。补一个参数校验：

// app/Http/Controllers/Api/ReportController.php

/**
 * 获取报表
 * 
 * GET /api/report/orders?since=2024-03-13
 */
public function orders(Request $request): JsonResponse
{
    $since = $request->query('since', now()->subDays(1)->toDateTimeString());

    // 最多允许查30天内的数据，防止全表索引扫描
    $maxSince = now()->subDays(30);
    if ($since < $maxSince->toDateTimeString()) {
        throw new ValidationException('since 参数不能早于30天前');
    }

    $orders = $this->reportService->getOrdersSince($since);

    return response()->json([
        'code'    => 0,
        'data'    => $orders,
        'total'   => count($orders),
    ]);
}

这样即使有人传恶意参数，也最多扫描30天的索引范围，不会拖垮数据库。

4.5 PHP-FPM调优：避免单点瓶颈

修复了慢SQL之后，FPM配置也要一并优化。原有的 pm.max_children=20 在8核16G的机器上偏保守。实测每个PHP-FPM进程空闲时占约45MB内存，16G内存可以支撑更多的worker：

; /etc/php/8.3/fpm/pool.d/www.conf
; 原配置
; pm.max_children = 20
;
; 调整后
pm = dynamic
pm.max_children = 80            ; 8核机器，按每个请求200ms算，可支撑400 QPS
pm.start_servers = 30
pm.min_spare_servers = 20
pm.max_spare_servers = 40
pm.max_requests = 5000          ; 防止进程内存泄漏导致缓慢增长

; 关键：设置请求超时，防止慢请求占死worker
request_terminate_timeout = 30s

这里重点说 request_terminate_timeout。之前没设置这个，PHP脚本如果卡在某个外部IO上会无限等下去。设置30秒让FPM强制杀掉超时请求。同时 pm.max_requests 让worker处理5000请求后自动重启，防止PHP内存泄漏累积。

改完配置后记得重载：

sudo systemctl reload php8.3-fpm

4.6 Nginx侧优化：快速失败而不是排队

Nginx配置也做了调整。与其让请求在FPM队列里堆着，不如直接返回503。先看监控快速获得感知：

# /etc/nginx/nginx.conf 里加一层快速505保护
# 放在 http 块内

# 定义上游，重点：max_fails 和 fail_timeout
upstream php_fpm {
    server unix:/run/php-fpm/www.sock;
    keepalive 32;
}

server {
    listen 80;
    server_name api.example.com;

    # 把原来只给超时的配置换成「快速失败 + 合理超时」
    location ~ \.php$ {
        include snippets/fastcgi-php.conf;
        fastcgi_pass unix:/run/php-fpm/www.sock;

        # 连接超时：3秒连不上直接失败
        fastcgi_connect_timeout 3s;
        # 发送超时
        fastcgi_send_timeout 10s;
        # 读取超时：FPM处理超过10秒就断掉
        # 注意：不要设太长，否则用户等半天
        fastcgi_read_timeout 10s;

        # 失败重试配置：最多重试1次
        fastcgi_next_upstream error timeout;
        fastcgi_next_upstream_tries 1;
    }
}

fastcgi_connect_timeout 3s 保证了如果FPM没有及时accept，Nginx不会无限等下去。fastcgi_read_timeout 10s 比FPM的30秒短，让Nginx先断开，避免用户挂太久。但这只是兜底，真正问题是慢SQL，索引修好之后这些超时基本不会触发。

五、效果数据：压测对比

修复完成后，我用 ab（ApacheBench）压了线上接口，对比修复前后的表现。

压测命令：

# 参数：100个并发，总共10000个请求
ab -n 10000 -c 100 -H "Host: api.example.com" \
  http://127.0.0.1/api/report/orders?since=2024-03-13

压测结果：

指标	修复前	修复后（加索引+代码优化）	提升倍数
Requests per second	42.87	587.62	13.7x
Time per request (mean)	2331.84ms	170.18ms	13.7x
Time per request (mean, across all concurrent requests)	23.32ms	1.70ms	13.7x
Transfer rate	192.84 Kbytes/sec	2143.48 Kbytes/sec	11.1x
Complete requests	10000	10000	-
Failed requests	0	0	-
Non-2xx responses	0	0	-
99% response time	3.12s	0.21s	14.9x

线上生产数据：

504错误率：从37%降到0%（观察7天无复发）
P99延迟：从2080ms降到212ms
MySQL CPU使用率：从85%降到22%
PHP-FPM listen queue：从100以上降到0-2
单条SQL耗时：850ms降到12ms

这次故障影响时长为2小时19分。如果没有索引修复，即使调大Nginx超时，MySQL的负载也只会继续累积。最终的结果就是“雪崩”——MySQL彻底无法响应，所有请求超时。

六、为什么调超时没用？

很多人第一反应是调Nginx的 proxy_read_timeout。这里解释一下为什么这个方案在这里不适用：

你调大了Nginx超时，比如从60秒调到120秒。
Nginx确实会等更久，用户看到504的次数会减少。
但FPM的worker会在每个慢请求上卡更久。原本30秒的超时变成120秒，就意味着一个worker在报错前要占用4倍的时间。
流量不变时，FPM的20个worker会更快被占满。新请求直接排队，表现为 connect() timed out——还是504。
MySQL端，每一个慢SQL都在抢CPU和IO。400万行的全表扫描，一个请求850ms，一天几万个请求就是几十个小时的无效扫描。

所以，调超时的本质是「把问题往后拖延」，而不是解决。

七、为什么这个SQL之前没被发现？

很讽刺的是，这条SQL上线了大半年，之前一直跑在100ms以内。为什么？因为订单表当时只有40万行。全表扫描撑得住。

订单量涨了10倍，表涨到400万行，SQL就爆了。这是最典型的「SQL性能随着数据量增长而劣化」问题。

再深挖一层，开发环境里MySQL optimizer_switch 和线上的不一样，执行计划也不一样。开发库里只有几万行的表，MySQL优化器会认为全表扫描更快，压根不会选索引。

另一个原因：这个接口在测试环境根本没做过压测。测试环境数据量不是生产环境的量级，接口P95看着是200ms，但实际上生产环境早就是2秒了。区别只在数据量够不够大，能不能触发全表扫描的瓶颈。

八、避坑指南

这次故障踩了三个坑，每一个都直接浪费了排查时间。写出来，希望你少走弯路。

坑1：用 MySQL 的 SET GLOBAL 开启慢查询，忘了它是全局的

排查过程中我执行了 SET GLOBAL slow_query_log = 1，开了全局慢查询日志。这本身没错，但忘了它在新连接生效，老连接不生效。结果我在 /var/log/mysql/mysql-slow.log 里等了5分钟没看到任何输出。

后来发现，应用程序连接池里已经建立的长连接根本没拿到新的 slow_query_log 设置，所以在应用侧发起的慢查询都没记录。修复办法：要么重启连接池，要么直接在MySQL配置文件里加 slow_query_log=1 然后重启MySQL。

# 正确做法：直接写入配置文件
echo "
[mysqld]
slow_query_log = 1
slow_query_log_file = /var/log/mysql/mysql-slow.log
long_query_time = 1
log_queries_not_using_indexes = 1
" | sudo tee /etc/mysql/mysql.conf.d/slow-query.cnf

sudo systemctl restart mysql

重启后立刻生效，而且永久保留，不用每次排查都临时开启。

坑2：看到 connect() timed out 以为是Nginx问题，调了一晚上超时参数

我凌晨的排查时间里有40分钟浪费在改Nginx超时上。因为日志里写的是 connect() to unix:/run/php-fpm/www.sock failed: Connection timed out，第一反应是Nginx到FPM的连接有问题。

但这个超时是「FPM进程池满了，Unix Socket的backlog队列也满了」，不是网络问题。FPM没有能力接受新连接，内核Socket队列满了，Nginx的connect自然超时。

验证方法很简单：在服务器上用 ss -lx 看Unix Socket的接受队列：

ss -lx | grep php

如果 Recv-Q 等于或接近 Send-Q，说明队列满了。FPM侧已经堵死，Nginx怎么调都没用。

坑3：压测时忘了 TIME_WAIT 的问题，端口全被占满

用ab压测时，如果不设置keep-alive，每次请求都会新建TCP连接。我的压测开在服务器本机，源端口范围默认是 net.ipv4.ip_local_port_range。默认值通常是32768-60999，约28000个端口。

短连接压力下，TIME_WAIT状态的socket会积累，压测跑到第3万多个请求时，报错：

ab: Cannot assign requested address

这是本机端口耗尽，不是服务器问题。解决方法是压测时加上 keep-alive 参数，或者调大端口范围：

# 方法1：压测时用 keep-alive，避免大量 TIME_WAIT
ab -n 10000 -c 100 -k http://127.0.0.1/api/...

# 方法2：调大 ip_local_port_range
sudo sysctl -w net.ipv4.ip_local_port_range="1024 65535"

我用的是方法1，让压测和真实场景更接近（线上Nginx到FPM之间是长连接）。

坑4：索引加了，但线上还慢——因为查询没用上索引

修完后我发现一个奇怪现象：本地跑SQL只要12ms，但线上还是偶尔有300ms的请求。查了执行计划，发现线上MySQL优化器对某些 since 参数选择了全表扫描。

原因：当 since 参数太早（比如30天前），SQL要回的表行数超过全表扫描的代价阈值（eq_range_index_dive_limit，或者说 --maximum-composite-index-depth），优化器觉得走索引不如全扫。

解决办法是给查询加上 FORCE INDEX，强制用索引：

SELECT * FROM orders 
FORCE INDEX (idx_created_at_id)
WHERE created_at >= '2024-03-13 00:00:00' 
ORDER BY id DESC 
LIMIT 100;

或者在PHP代码里，如果用了Laravel：

// 强制走索引，防止优化器误判
DB::table('orders')
    ->select(['order_no', 'amount', 'status'])
    ->from(DB::raw('orders FORCE INDEX (idx_created_at_id)'))
    ->where('created_at', '>=', $date)
    ->orderByDesc('id')
    ->limit(100)
    ->get();

这算是个「黑魔法」，用了 FORCE INDEX 之后执行计划稳定了。但要特别注意：如果后续数据量继续增长，这个索引未必永远是最优的。必须定期review执行计划，或者用 ANALYZE TABLE 更新统计信息，让优化器有足够好的数据做决策。

九、最后：从故障到规范

这次故障修完了，但不能只修完就完。一个系统性的做法是把这次经验固化成规范，后续所有SQL变更强制执行慢查询检查。

我们做的三件事：

把 long_query_time=1 和 log_queries_not_using_indexes=1 永久写入MySQL配置，所有慢查询都记录。
代码评审增加一个硬性条件：所有SQL必须贴 EXPLAIN 截图，rows 不能超过1万。
给Grafana加了一个面板：监控PHP-FPM的 listen queue 和MySQL的 Rows_examined 总和。任何一个超过阈值就直接告警。

这个监控面板的告警规则长这样：

# grafana-alert.yaml
groups:
  - name: mysql-health.rules
    rules:
      - alert: HighRowsExamined
        expr: rate(mysql_global_status_handler_read_rnd_next[5m]) > 100000
        for: 10m
        labels:
          severity: critical
        annotations:
          summary: "MySQL全表扫描过高，5分钟平均每秒扫描行数超过10万"
          description: "当前值 {{ $value }}，可能存在大量未走索引的查询"

      - alert: FpmQueueGrowing
        expr: mysql_slow_queries_total > 100
        for: 15m
        labels:
          severity: warning
        annotations:
          summary: "MySQL慢查询数量超过100"
          description: "15分钟内慢查询数超过100，请检查慢查询日志定位问题SQL"

10个月过去了，这套配置帮我们提前发现了3次潜在的慢SQL问题，都是在影响线上之前就被拦截了。每次都是同一个原因：新上线的功能，SQL没走索引，数据量上来之后开始变慢。

现在这套排查路径已经是团队的标准SOP：
Nginx error log → PHP-FPM status → strace进程 → MySQL慢查询 → EXPLAIN → 加索引/改SQL → 压测验证。

如果你也在处理502/504，按照这条路径走一遍，80%的根因能在30分钟内定位。剩下的20%，大概率在外部依赖（Redis、第三方API、消息队列消费堆积），那是另一篇文章的主题。