Nginx 与 PHP-FPM 慢请求四层定位实战：request_time 拆解、slowlog 调用栈、MySQL 慢日志与模板层排查

  1.  Home
  2. Text  
    3. Share to：

先分清：是"慢"还是"错"

本站用的是 Typecho，跑在 PHP 上。日常最常接到的反馈是"网站打不开了"或者"网站很慢"，这两句话背后其实是两条完全不同的排查路径。慢，说明请求最终有响应，只是耗时超标；错，说明响应码不是 200，或者干脆没有响应。把这两件事混在一起查，会浪费大量时间。

我见过的典型误区是这样的：网站上出现 502，站长的第一反应是"PHP 是不是太慢了"，于是去调 max_execution_time、去加 pm.max_children，结果一无所获。实际上 502 是 Nginx 说的："我连不上上游"，跟上游执行了多久完全无关。调执行时间对 502 一点用都没有。

所以这个诊断方法的第一条原则是：先看状态码，再谈耗时。本文只处理一种情况——Nginx 给 PHP-FPM 设了 fastcgi_read_timeout 60s，页面偶尔超过 60 秒导致 504，或者干脆就是"某几个页面要转好几秒"。

第一层：Nginx 的 $request_time 到底包了什么

打开 Nginx 的 access log，看 $request_time。$request_time 是从 Nginx 收到客户端第一个字节，到把最后一个响应字节发给客户端的总时长。它包含三段：

request_time = upstream_connect_time + upstream_header_time + upstream_body_time + 边缘开销

更实用的拆法是看另外三个变量：

  • $upstream_connect_time：Nginx 连 PHP-FPM 的耗时（走 Unix socket 时几乎是 0；走 TCP 时偶尔会有几十毫秒，说明 backlog 排队）
  • $upstream_header_time（TTFB）：PHP-FPM 开始吐出响应头的耗时，这段时间 PHP 在干活
  • $upstream_response_time：从连接成功到完整收到上游响应的耗时

把这几个变量都打进日志，是诊断的第一步，也是很多人一直没做的一步。默认的 combined 格式里只有 $request_time，什么都看不出来：

log_format timing '$remote_addr - $request '
    'rt=$request_time uct=$upstream_connect_time '
    'uht=$upstream_header_time urt=$upstream_response_time '
    '$request_method $uri $status';

然后从日志里把慢请求捞出来：

awk -F'rt=' '$2+0 > 3 {print}' /var/log/nginx/access.log | tail -30

假设你捞到这么一行：rt=8.203 uct=0.000 uht=8.190 urt=8.201 $request_method=GET /archives/123/ 200。三个数字放在一起，结论立刻出来了：连接耗时 0，TTFB 8.19 秒（几乎等于总耗时），说明这 8 秒几乎全花在 PHP 执行上，不是网络、不是 Nginx、也不是响应体传输。这是最常见的一种。

再假设另一种：rt=8.203 uct=0.002 uht=0.015 urt=0.016。PHP 只用了 16 毫秒，但总耗时 8.2 秒。那 8 秒花在哪？多半是客户端下载慢（带宽、CDN 回源链路），或者 Nginx 发出去的响应体特别大。这时候你去查 PHP 会一无所获，应该去看响应体大小（$body_bytes_sent）和客户端地区。

还有一种很隐蔽的：uct=0.5。连接 FPM 花了 500 毫秒，这说明 FPM 的 listen backlog 队列满了，请求在排队等空闲 worker。这是容量不足的明确信号，不是代码问题。

第二层：PHP-FPM 的 slowlog，比任何推测都准

确认了 TTFB 高，下一步就是让 PHP 自己说出它卡在哪一行。PHP-FPM 内置了一个专门干这事的功能——slowlog，但默认是关闭的。

先看池配置 /etc/php/8.2/fpm/pool.d/www.conf（路径随发行版和版本变化）：

request_slowlog_timeout = 5s
slowlog = /var/log/php-fpm/slow.log
request_terminate_timeout = 60s

request_slowlog_timeout = 5s 的意思是：任何一个请求执行超过 5 秒，FPM 就把它当前的 PHP 调用栈 dump 到 slowlog 里。注意它不杀死请求，只是记录，所以开着它对线上完全无害，代价极小。这一点很多人搞错了，以为设了就会中断，于是不敢开。

request_terminate_timeout = 60s 才是真正强杀。它和 Nginx 的 fastcgi_read_timeout 应该手动对齐：如果 Nginx 60 秒就放弃，而 FPM 允许跑 300 秒，那 FPM 会白跑 4 分钟，还占着 worker 名额；反过来说 FPM 30 秒就杀，Nginx 却在等 60 秒，那客户端会等到一个 504。两边给一样的值，日志才对得上。

改完池配置之后，如果只 systemctl reload php8.2-fpm，request_slowlog_timeout 这类指令在某些版本上不会生效，必须 restart。安全起见：先 php-fpm -t 检查配置语法，再 restart。

slowlog 里的内容长这样：

[07-Nov-2026 14:22:31]  [pool www] pid 21887
script_filename = /var/www/zz1984/index.php
[0x00007f2c8a1b3a40] sleep() /var/www/zz1984/var/Widget/Archive.php:412
[0x00007f2c8a1b2c10] execute() /var/www/zz1984/var/Widget/Archive.php:207
[0x00007f2c8a1b1d90] render() /var/www/zz1984/index.php:31

读法是自下而上：最下面是被调用的入口，最上面是此刻正在执行的那个函数。上面这行告诉你，PHP 卡在 Archive.php:412 的 sleep() 上——虽然这里只是个示例，但思路是一样的：栈顶一定告诉你真正的位置。三次采样落在同一行，基本可以确诊。

如果栈顶是数据库操作（Typecho_Db::query()、mysqli_query()、PDOStatement::execute()），但没告诉你具体是哪条 SQL，那就得配合 MySQL 的慢查询日志（下面第三层）。

第三层：MySQL 慢查询日志，把 SQL 抓现行

PHP 的栈顶告诉你是"某一次查询"，MySQL 的慢日志告诉你是"具体哪条语句"。开启方式（MySQL 8.0）：

SET GLOBAL slow_query_log = ON;
SET GLOBAL long_query_time = 1;
SET GLOBAL log_queries_not_using_indexes = ON;
SET GLOBAL slow_query_log_file = '/var/log/mysql/slow.log';

这里有个大坑：slow_query_log_file 和 log_queries_not_using_indexes 是 SESSION/Global 双层的，但修改后只对新连接生效，而且 SET GLOBAL 重启即失效，要写进 my.cnf 才持久。long_query_time 尤其要小心：它是"执行时间超过这个阈值才记录"，等于不算，边界是严格的 >。

另外 log_queries_not_using_indexes = ON 在数据量大的站上会写爆磁盘。它记录的是"没有用索引的查询"，小表全表扫描（比如只有 20 行分类表）也会被记下来。我的建议是：只在定位阶段开，定位完立刻关。长期开启的正确姿势是配合 min_examined_row_limit = 1000，只看扫描行数上千的。

看日志不要直接 cat，用官方的汇总工具：

mysqldumpslow -s t -t 20 /var/log/mysql/slow.log     # 按总耗时排序取前 20
pt-query-digest /var/log/mysql/slow.log               # Percona 版，按指纹归并

mysqldumpslow 是 MySQL 自带的（Debian 下要装 mysql-client 才有）。它的 -s t 按总时间排、-s c 按次数排、-s al 按平均锁时间排。很多时候"总耗时最多的 SQL"和"单次最慢的 SQL"完全不是同一条——前者往往是一条只用 20 毫秒但每秒打 200 次的查询，后者是偶发的全表扫描。两个都要看。

对每一条上榜的 SQL，用 EXPLAIN 确认执行计划，重点看三列：type 是 ALL（全表扫描）还是 ref/range；rows 预估值是不是远大于实际返回的行数；Extra 里有没有 Using filesort 或 Using temporary。Typecho 的文章列表页是典型场景：按 created 倒序 + status = 'publish' 筛选 + 分页，没有 (status, created) 复合索引时就会退化成全表扫描加 filesort。

顺带一查：别把 502 也当"慢"

既然开了 slowlog，顺手提供一个对照：如果日志里 Nginx 一侧的 upstream_header_time 是 - 或者干脆整行为 502，那说明请求压根没进到 PHP。这时看 /var/log/nginx/error.log，出现频率最高的三种分别是：connect() to unix:/run/php/php8.2-fpm.sock failed (11: Resource temporarily unavailable)——FPM 的 backlog 满了，worker 全占着；(2: No such file or directory)——socket 路径不对或者 PHP-FPM 根本没起来；upstream prematurely closed connection——PHP 进程被 OOM killer 杀了，去 dmesg -T | grep -i "killed process" 确认。

这三种统统不是"慢"，调超时参数一个都解决不了。第一种要加 pm.max_children 或者找出占着 worker 的慢请求（正好回到本文第三条路径）；第二种查 systemctl status php8.2-fpm；第三种要么加内存、要么给 FPM 的 pm.max_children 设一个合理的上限并用 pm.max_requests = 500 定期回收 worker，避免单个进程内存持续膨胀。

第四层：别忽略模板渲染，Typecho 的 Theme 层

数据库也快、PHP 函数也不慢，页面还是要好几秒，那是渲染问题。Typecho 的模板是 PHP 原生的，模板里写什么都会执行。几个高发的写法：

  • 在 header.php 或 sidebar.php 里循环查询（比如为了做"最新 10 条评论"、"标签云"再跑一次 $this->db->query()），每个页面都会多打几次库
  • 在循环里调用 $this->related() 或类似函数，文章数 × 查询数
  • 模板里直接 file_get_contents('https://外部接口')，一个同步 HTTP 请求就把首屏拖慢 1 秒

诊断方法很简单：在 config.inc.php 里打开 Typecho 的 debug（define('__TYPECHO_DEBUG__', true);），或者临时在 index.php 结尾打印 $this->db->getCount()。一个首页打 50 次库，基本上就是模板层的问题，跟 PHP 性能和数据库性能都没关系。

顺带一个特别常见的"慢"：图片和静态资源慢，但 HTML 其实很快。如果你只看 $request_time，会以为是 PHP 问题。所以我在日志里还单独给静态资源打一个 log：

location ~* \.(jpg|jpeg|png|gif|webp|css|js|woff2)$ {
    log_format static '$request_time $body_bytes_sent $uri';
    access_log /var/log/nginx/static.log static;
    expires 30d;
    add_header Cache-Control "public, immutable";
}

如果 static.log 里单个 400KB 的图要 2 秒，那是带宽问题，应该上 CDN，跟 PHP 完全无关。

一套可复用的诊断顺序

把上面四层收成一张清单，下次再遇到"网站慢"，照着走一遍，最多 20 分钟：

  1. curl -o /dev/null -s -w '%{time_starttransfer}\n' https://站点/ 先确认 TTFB 是否真的高。如果 TTFB 只有 200 毫秒，那"慢"是前端资源问题，直接跳到静态资源排查。
  2. 看 Nginx 日志的 uht 和 urt。uht 高 → PHP 问题，进第 3 步；uht 低但 rt 高 → 传输/带宽问题。
  3. 开 request_slowlog_timeout，等 5 分钟，读 slowlog 的栈顶。栈顶是 DB → 进第 4 步；栈顶是 file/curl/sleep → 直接是代码问题。
  4. 开 MySQL 慢日志，mysqldumpslow -s t 看前 10 条，逐条 EXPLAIN，补索引。
  5. 都正常但还慢 → 查模板执行了多少次查询，查是否同步调外部接口。
  6. 最后再考虑机器资源：top 看 %wa（IO 等待）、si/so、load average。如果是 4 核机器 load 12 并且 %wa 超过 20%，那是磁盘 IO 瓶颈，调代码没用，该换 SSD 或加缓存。

这套顺序的价值在于：每一步都能把问题范围砍掉一半，而不是靠猜。我最烦看到的一种排查是"我把 max_execution_time 从 30 调到 300，好像好了"——那不是修好了，那是把问题从"报错"变成"转三分钟然后白屏"。真正的修好，是 slowlog 里再也抓不到那条慢请求。

Last modification：November 9th, 2026 at 08:25 pm
© 允许规范转载

相关文章

Leave a Comment