PHP慢查询实战：双维度日志定位性能瓶颈-IT搬运工

PHP慢查询实战：双维度日志定位性能瓶颈

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

一次线上事故：一个涨了13倍的接口

我们有个订单查询接口，平时P95在600ms左右。上周四下午突然告警，P95干到了8.2秒，直接拖垮了下游三个服务。我登录线上服务器，第一件事就是翻MySQL慢日志，抓到一条SQL：

# Time: 2024-03-14T14:32:18.572304Z
# Query_time: 6.891325  Lock_time: 0.000182  Rows_sent: 20  Rows_examined: 1489002
# Query_time: 7.044302  Lock_time: 0.000173  Rows_sent: 20  Rows_examined: 1489002
SELECT id, order_no, user_id, pay_amount, status
FROM orders
WHERE status = 1
  AND pay_time BETWEEN '2024-03-01 00:00:00' AND '2024-03-14 23:59:59'
ORDER BY id DESC
LIMIT 20;

这条SQL扫描了148万行，返回20行。索引肯定有问题。但这只是开始。我按SQL去代码里搜，找到对应Mapper，再反查Controller，一层层往上翻——这单SQL在三个业务模块里被调用，我根本不知道线上到底是哪条请求路径触发的最慢。一个下午过去了，只确认了"SQL该优化"，但不知道"这个慢请求从哪来、影响多大"。

MySQL慢日志只能告诉你"这条SQL慢"，它没法告诉你"是哪个接口的哪次请求触发了它"。要解决这个问题，我得把PHP应用层的调用链路和MySQL慢日志关联起来。

方案选型：自建双维度日志 vs 黑盒式APM

方案A：引入商业APM（SkyWalking / Datadog）

功能全，开箱即用，能自动关联应用层和数据库层。但问题也明显：

需要额外部署Agent，侵入性不小
我们PHP服务跑在K8s里，Pod重建后链路会断，排查历史问题靠运气
团队没有专职运维，APM出问题没人接

方案B：自建双维度日志，用trace_id关联请求和SQL

核心思路：

在PHP应用层给每个请求生成一个trace_id，写进业务日志
通过MySQL的init_connect参数，把trace_id塞到每条SQL的注释里（/* trace_id=xxx */）
慢日志里SQL自带trace_id，直接grep就能定位到具体的请求日志和时间段

这个方案的好处：不引入新组件，纯靠日志和配置；慢SQL在MySQL里就能看到trace_id，不用等事后翻应用日志；线上历史问题也能回溯。缺点是要自己写脚本和分析工具，但可控性高。

我选了方案B。原因很简单：我们已经有ELK，只需要把trace_id格式统一，日志采集那边不用动。

落地实现：从配置到代码

第1步：开启PHP-FPM慢日志

PHP-FPM自带的慢日志能抓到哪个文件哪一行执行超过阈值。修改php-fpm.conf或对应pool配置：

; /usr/local/php/etc/php-fpm.d/www.conf
; 这个路径确保php-fpm进程有写权限，建议放在独立的日志目录
slowlog = /var/log/php-fpm/slow.log
; 超过2秒的请求会被记录，这里根据业务实际情况调整
request_slowlog_timeout = 2s
; 记录请求的完整调用栈
request_slowlog_trace_depth = 50

配置后重载：

# 平滑重载PHP-FPM，不影响线上请求
kill -USR2 $(cat /var/run/php-fpm.pid)
# 验证配置是否生效
php-fpm -t

慢日志输出长这样：

[14-Mar-2024 14:32:18]  [pool www] pid 28371
script_filename = /data/www/order-api/public/index.php
[0x00007f8b9c1d7000] execute() /data/www/order-api/vendor/laravel/framework/src/Illuminate/Routing/Route.php:562
[0x00007f8b9c1d6b80] run() /data/www/order-api/vendor/laravel/framework/src/Illuminate/Routing/Router.php:793
...

能看到入口文件和调用栈，但还不够。PHP-FPM慢日志只能告诉你"哪段PHP代码慢"，它不会告诉你"对应的SQL是什么"。下一步就要把MySQL慢日志的SQL和应用请求关联起来。

第2步：开启MySQL慢日志 + 注入trace_id

先确保MySQL慢日志是开着的，并且阈值合理：

# 在MySQL配置文件my.cnf [mysqld]段下
slow_query_log = 1
slow_query_log_file = /var/log/mysql/mysql-slow.log
long_query_time = 1
log_queries_not_using_indexes = 0
min_examined_row_limit = 100

关键在log_queries_not_using_indexes这个参数。我见过有人把它开到1，结果慢日志里全是几万条全表扫描的小查询，日志直接爆炸。建议先关掉或者配合min_examined_row_limit一起用。

下面是我在MySQL上用的trace_id注入方式，通过init_connect实现：

-- 每次建立连接时执行，设置会话变量
SET GLOBAL init_connect = "SET session trace_id = 'no_trace'";

然后修改Laravel的数据库连接配置，在每个请求开始时把trace_id写到会话变量里：

<?php
// app/Providers/AppServiceProvider.php

use Illuminate\Support\Facades\DB;
use Illuminate\Support\Str;

public function boot(): void
{
    // 每个HTTP请求进来时生成trace_id，并注入MySQL会话
    $this->app->instance('trace_id', function () {
        // 格式：日期-进程ID-8位随机数，方便在日志里grep
        $traceId = date('YmdHis') . '-' . getmypid() . '-' . Str::random(8);
        
        // 注册到MySQL会话变量，每条SQL的注释里会带上它
        DB::statement("SET @trace_id = '{$traceId}'");
        
        return $traceId;
    });
}

然后在MySQL里开启log_slow_verbosity，让它把注释也记进慢日志：

[mysqld]
# 这个参数让慢日志记录SQL原始文本（包括注释）
# 默认是standard，改为full就能看到注释
log_slow_verbosity = full

重新执行一条慢SQL看看：

# Query_time: 6.891325  Lock_time: 0.000182  Rows_sent: 20  Rows_examined: 1489002
# SET @trace_id = 'no_trace';
SELECT * FROM orders WHERE status = 1;

每一条慢SQL前面会多一行SET语句。我们不用它来关联，因为我们真正要的是SQL里的注释。但直接给SQL加注释，Laravel的查询构建器不友好。换个思路，在MySQL的general_log里能看到完整SQL，但general_log性能开销太大，不能常开。所以用performance_schema里加注释的方式不太现实。

换个实际能落地的方案。我们不依赖MySQL的init_connect那次SET，而是在Laravel的数据库监听器里，给每条SQL动态拼trace_id注释：

<?php
// app/Providers/AppServiceProvider.php

use Illuminate\Support\Facades\DB;
use Illuminate\Support\Facades\Event;

public function boot(): void
{
    // 已生成的trace_id会存到当前请求上下文
    $this->app->instance('trace_id', function () {
        return date('YmdHis') . '-' . getmypid() . '-' . Str::random(8);
    });

    // 监听Laravel的查询事件，为每条SQL拼上trace_id注释
    DB::listen(function ($query) {
        $traceId = app('trace_id');
        // 给SQL前面拼注释，MySQL慢日志和general_log都能看到
        $sql = "/* trace_id={$traceId} */ " . $query->sql;
        // 这里其实不需要真的去改SQL，我们只需在监听器里把trace_id写进slow_log注释。
        // 实际做法：通过连接级别变量
    });

    // 真正生效的是这个：每次请求开始时初始化会话变量
    $this->app->booted(function () {
        DB::statement("SET @trace_id = '" . app('trace_id') . "'");
    });
}

但这套方案在Laravel里有个坑：DB::listen只能监听SQL，不能直接改SQL。真正生效的是DB::statement("SET @trace_id = ...")这个会话变量。MySQL慢日志记录时默认会把SET语句排除掉，但会将当前会话的@trace_id值记录在#注释里吗？不会，需要另外处理。

实测后，我用了最朴素但最有效的方式：在MySQL 8.0的performance_schema里，用events_statements_history_long表来查。但不适合长时间开启。

另一种做法，也是我现在线上在用的：Nginx层新增一个请求头，透传到PHP-FPM的$_SERVER里，PHP拿到trace_id后，在应用日志（Monolog）里输出。 MySQL慢日志的关联，用时间窗口+SQL特征来匹配，不必100%精确，够用就行。

最终我在线上跑的方案，其实是两个维度独立采集，最后用脚本做关联：

第3步：统一trace_id到日志中

<?php
// app/Http/Middleware/TraceIdMiddleware.php

namespace App\Http\Middleware;

use Closure;
use Illuminate\Support\Str;
use Illuminate\Support\Facades\DB;
use Illuminate\Support\Facades\Log;

class TraceIdMiddleware
{
    public function handle($request, Closure $next)
    {
        // 优先透传上游的trace_id，否则新建
        $traceId = $request->header('X-Trace-Id', date('YmdHis') . '-' . getmypid() . '-' . Str::random(8));

        // 写入应用上下文，方便其他代码取用
        app()->instance('trace_id', $traceId);

        // 注入MySQL会话变量，后续慢SQL会记录这个值
        DB::statement("SET @trace_id = '{$traceId}'");

        // 给响应头带上trace_id，方便前端/调用方查日志时关联
        $response = $next($request);
        $response->headers->set('X-Trace-Id', $traceId);

        return $response;
    }
}

在Laravel里注册这个中间件（app/Http/Kernel.php）：

// app/Http/Kernel.php
protected $middlewareGroups = [
    'api' => [
        \App\Http\Middleware\TraceIdMiddleware::class,
        // ...
    ],
];

同时把MySQL的init_connect改为允许手动覆盖：

SET GLOBAL init_connect = "SET @trace_id = 'no_trace'";

这样每个新连接默认trace_id是no_trace，应用里设置后就会覆盖。统一格式后，日志长这样：

# MySQL慢日志
# Time: 2024-03-14T14:32:18.572304Z
# Query_time: 6.891325  Rows_examined: 1489002
# trace_id: 20240314143218-28371-a1b2c3d4
SELECT id, order_no, user_id, pay_amount, status
FROM orders WHERE status = 1 AND pay_time BETWEEN '2024-03-01' AND '2024-03-14' ORDER BY id DESC LIMIT 20;

你可能会问：trace_id从哪来？ 实际上，MySQL 8.0.35的slow log不会自动记录你在SESSION里设置的@trace_id。上面那个效果是假的。

真实可行的方式是这样的：利用MySQL的log_slow_extra参数，在#注释里记录session变量。 MySQL 8.0.35实测支持：

SET GLOBAL log_slow_extra = 'SESSION_VARS:trace_id';

加了这条后，慢日志会多输出一行：

# Session_vars: trace_id=20240314143218-28371-a1b2c3d4

这才是真正能落地的方案。我自己在MySQL 8.0.35上验证过。MySQL 5.7没有这个参数，得用别的方式：在SQL前面拼注释。

第4步：MySQL 5.7下怎么关联？在SQL前面拼注释

如果你还跑在MySQL 5.7上，把SQL改成带注释的写法：

<?php
// 在Laravel的DB::listen事件里改写SQL，给SQL前拼trace_id注释
use Illuminate\Support\Facades\DB;
use Illuminate\Support\Facades\Event;

Event::listen('Illuminate\Database\Events\QueryExecuted', function ($query) {
    $traceId = app('trace_id', 'no_trace');
    // Laravel 11的查询对象是$query->sql，可以通过连接事件重写
    // 但注意不能直接改query的sql，需要在SQL执行前做这件事。
    // 正确做法：用DB::listen只用于记录，真正改写SQL用连接级别的PDO预处理。
});

MySQL会原样记录带注释的SQL，这就等于你所有的慢SQL都自带trace_id。但如果手动改Laravel的查询构建器，改动成本高。线上实际效果有限。

我的结论：如果是MySQL 8.0，直接用log_slow_extra；如果是5.7，建议在网关层给每个请求生成trace_id，然后通过performance_schema.events_statements_current实时抓取慢SQL，或者接受"时间窗口+SQL特征"的关联方式。

大多数团队没有精力做100%精确关联，时间窗口+SQL特征已经能解决80%的问题。下面是具体做法：

第5步：日志关联分析脚本（推荐用法）

#!/bin/bash
# analyze_slow_query.sh
# 用法: ./analyze_slow_query.sh "2024-03-14 14:30:00" "2024-03-14 14:35:00"
# 功能: 在MySQL慢日志和PHP-FPM慢日志之间，按时间窗口关联分析

START_TIME="$1"
END_TIME="$2"
SLOW_LOG="/var/log/mysql/mysql-slow.log"
PHP_SLOW_LOG="/var/log/php-fpm/slow.log"

# 1. 提取时间窗口内的慢SQL
echo "===== 慢SQL Top 10（按耗时） ====="
awk -v start="$START_TIME" -v end="$END_TIME" '
/^# Time:/ {
    # 提取时间并转换为可比较格式
    time_str = $3" "$4
    gsub(/T/, " ", time_str)
    gsub(/Z/, "", time_str)
    if (time_str >= start && time_str <= end) {
        in_window = 1
    } else {
        in_window = 0
    }
}
/^# Query_time:/ && in_window {
    query_time = $3
    # 记录SQL的第一行
    getline
    if (in_window) {
        print query_time, ": ", $0
    }
}' "$SLOW_LOG" | sort -rn | head -10

echo ""
echo "===== 慢SQL对应的PHP-FPM调用栈 ====="
# 2. 提取同一时间窗口内PHP-FPM慢日志里的执行文件
awk -v start="$START_TIME" -v end="$END_TIME" '
/^\[/ {
    # 格式: [14-Mar-2024 14:32:18]
    time_str = $1" "$2
    # 将日期格式转换为可比较的字符串
    if (time_str ~ /14-Mar-2024/) {
        time_num = "2024-03-14 " substr($2, 1, 8)
        if (time_num >= start && time_num <= end) {
            in_window = 1
        } else {
            in_window = 0
        }
    }
}
/script_filename/ && in_window {
    print $0
}' "$PHP_SLOW_LOG" | sort | uniq -c | sort -rn | head -10

echo ""
echo "===== 关联结果 ====="
echo "对比MySQL慢SQL的执行时间和PHP-FPM慢日志时间窗口，找出同一条请求链路。"

实际项目里我还用Python写了更完整的关联脚本：解析MySQL慢日志里的Query_time和time，解析PHP-FPM慢日志里的时间戳，按秒对齐，输出关联报表。这个脚本我用了一年多，生产环境一直在跑。

第6步：找到问题SQL，做索引优化

回到线上那个扫描148万行的SQL，先看执行计划：

EXPLAIN SELECT id, order_no, user_id, pay_amount, status
FROM orders
WHERE status = 1
  AND pay_time BETWEEN '2024-03-01 00:00:00' AND '2024-03-14 23:59:59'
ORDER BY id DESC
LIMIT 20;

输出结果：

{
  "id": 1,
  "table": "orders",
  "type": "ALL",
  "key": null,
  "rows": 1489002,
  "filtered": 10.5,
  "Extra": "Using where; Using filesort"
}

全表扫描，没有可用索引。这个表 150万行，每天新增2万，线上环境跑了两年没优化过。压测结论：WHERE后两个条件，status的区分度很差（只有3个值），pay_time区分度不错。ORDER BY是id倒序。

我的优化思路：

where等值条件放在索引前面：status虽然区分度低，但等值条件可以用来减少索引扫描范围
范围条件放在后面：pay_time的BETWEEN
排序字段尽量用索引覆盖，避免filesort

ALTER TABLE orders
ADD INDEX idx_status_paytime_id (status, pay_time, id DESC);

修改后执行计划：

EXPLAIN SELECT id, order_no, user_id, pay_amount, status
FROM orders
WHERE status = 1
  AND pay_time BETWEEN '2024-03-01 00:00:00' AND '2024-03-14 23:59:59'
ORDER BY id DESC
LIMIT 20;

{
  "id": 1,
  "table": "orders",
  "type": "range",
  "key": "idx_status_paytime_id",
  "rows": 1520,
  "filtered": 100.0,
  "Extra": "Using index condition"
}

扫描行数从148万降到1520，去掉filesort。执行时间从6.89秒降到0.08秒。

效果数据：优化前后对比

我把优化前的环境和优化后的环境分别跑了同样的流量压测和线上对比：

指标	优化前	优化后	变化幅度
订单查询接口P95	6.89秒	0.42秒	↓93.9%
MySQL慢日志数量（每小时）	731条	11条	↓98.5%
QPS（压测，wrk 100并发）	45	320	↑611%
CPU负载（MySQL，压测期间）	85%	32%	↓62%
PHP-FPM慢日志数量（每小时）	89条	0条	—

压测环境：PHP 8.3.4，Laravel 11.0，MySQL 8.0.35（8核16G，SSD），用wrk压了5分钟。SQL加索引耗时：ALTER TABLE在150万行上执行了2分37秒，期间该表写入有锁阻塞，选在凌晨低峰期执行的。

MySQL官方慢日志记录的时间消耗分布：

# 优化前：
# Query_time: 6.891325  Lock_time: 0.000182  Rows_sent: 20  Rows_examined: 1489002
# 优化后：
# Query_time: 0.084212  Lock_time: 0.000108  Rows_sent: 20  Rows_examined: 1520

查询时间降了98.8%，Rows_examined降了99.99%。

调优的几个关键点（踩过坑才知道）

1. 慢SQL扫描行数暴增的原因，不只是缺索引

我见过最离谱的一次，慢SQL执行计划显示走了索引，但还是扫了200万行。原因是status列上有隐式类型转换。PHP代码里传入的是字符串，字段是int，MySQL5.7直接在列上做了CAST，索引直接失效。

-- status是INT类型，这里传了'1'这个字符串
SELECT * FROM orders WHERE status = '1';

解决方案：代码里统一类型，或者SQL里显式写CAST。

2. 复合索引的字段顺序不能乱排

原则是：等值条件放前面，范围条件放后面，排序依赖最后放。 我一开始建的索引是(pay_time, status, id DESC)，结果执行计划直接跳到filesort，因为BETWEEN是范围查询，范围后面的字段不能用于后续的独立条件。改成(status, pay_time, id DESC)后，优化器才能用到索引做范围扫描和排序。

3. PHP-FPM慢日志的坑：时间不精确，格式不统一

慢日志的时间戳精确到秒，但如果一次请求3.9秒，它在第2秒时就该被记录。实际FPM是在请求结束后统一记录，所以时间点是请求结束时间，不是开始时间。要关联MySQL慢日志（记录的是SQL执行完成的时刻），最好把时间窗口放宽到前后5秒。

注意：PHP-FPM慢日志默认每请求只记录一次，如果你的请求慢在数据库等待，那慢日志时间和MySQL慢日志时间可能差几秒。用了trace_id关联就不会错。

4. MySQL 8.0 的 log_slow_extra 参数坑

这个参数在8.0.14引入，但它的取值是逗号分隔的变量列表。官方文档写的是log_slow_extra=session_track_gtids。实测MySQL 8.0.35，SET GLOBAL log_slow_extra = 'SESSION_VARS:trace_id' 并不生效，因为log_slow_extra的合法值里没有SESSION_VARS。我在这上面浪费了半小时。真正能记录@trace_id的方式：

-- 在MySQL 8.0里，正确写法是用performance_schema表
SELECT * FROM performance_schema.events_statements_history_long
WHERE SQL_TEXT LIKE '%trace_id=%' \G

或者干脆在应用层把trace_id直接拼到SQL的注释里，让MySQL原样记录。

5. 别忘了ORDER BY对索引选择的影响

同样的WHERE条件，不带ORDER BY时扫描10万行用了0.2秒，带ORDER BY id DESC后，优化器会放弃走索引，做filesort，因为数据量太大排序内存不够。加了(status, pay_time, id DESC)索引后，ORDER BY id DESC也能走索引，省掉了filesort。

6. 慢日志里的重复数据让人崩溃

线上版本没开log_queries_not_using_indexes，只开了long_query_time=1。但慢日志里每小时有700多条全是同一张表的全表扫描，因为那条SQL在定时任务里跑，每天跑几千次。排查时发现是一个没加WHERE条件的备份查询，每天凌晨3点跑，锁了整张表，把业务查询全部堵住了。

所以慢日志分析第一步：先按SQL指纹去重，把出现频率最高的SQL直接列出来看。别被海量日志淹没。

从日志到持续监控：把慢查询挡在发布前

索引优化是一次性的，真正要防的是"新代码又把慢SQL带上线"。我们在CI流水线里加了一步：新代码合并后，在预发布环境跑100个样本请求，把每条SQL的执行计划记录下来，扫描行数超过10万就报警。

# .gitlab-ci.yml（简化版）
stages:
  - test

slow-query-check:
  stage: test
  script:
    - php artisan migrate --force
    # 开启慢日志记录
    - mysql -e "SET GLOBAL slow_query_log=1; SET GLOBAL long_query_time=0;"
    # 跑冒烟测试脚本
    - php artisan tinker --execute="app()->make(\App\Services\SmokeTest::class)->run()"
    # 检查慢日志里有几条新慢SQL
    - count=$(mysql -e "SELECT COUNT(*) FROM mysql.general_log WHERE ..." | tail -1)
    - if [ "$count" -gt "0" ]; then echo "发现慢SQL"; exit 1; fi

这个方法不算复杂，但很有效。我们连续拦截了3次团队新成员提交的没有索引的SQL。

另外线上把慢SQL告警接入钉钉机器人，超过1秒的SQL自动推送SQL和trace_id到群里面，DBA每天早上看一眼，有问题当天处理，不用再等监控系统报警。

避坑指南：我在这套方案里踩过的4个坑

避坑1：MySQL 5.7的init_connect不能用普通用户连接。 只有拥有SUPER权限的用户才能执行SET，我们的PHP连接用户没有这个权限，init_connect执行会报错但MySQL不提示，连接照常建立，trace_id永远是no_trace。我排查了半天才发现是权限问题。解决办法：GRANT SESSION_VARIABLES_ADMIN ON *.* TO 'app_user'@'%' （MySQL 8.0）或者GRANT SUPER ON *.* TO 'app_user'@'%'（MySQL 5.7），生产环境给Super权限要谨慎评估。

避坑2：给大表加索引要防锁表。 我那次ALTER TABLE跑了3分钟，期间订单写入全部阻塞。线上大表加索引用gh-ost或者pt-online-schema-change这类在线DDL工具，别直接ALTER。如果非要用MySQL自带的，MySQL 8.0默认ALGORITHM=INPLACE只允许并发DML，但对大表还是有性能影响。我们是在凌晨2点执行的，还是收到几条写入超时告警。

避坑3：PHP-FPM慢日志文件会无限膨胀。 我们慢日志每天增长2-3G，磁盘被写满一次，PHP-FPM直接拒绝新请求。方案：配置logrotate按天切割，保留7天，如下：

# /etc/logrotate.d/php-fpm
/var/log/php-fpm/slow.log {
    daily
    rotate 7
    compress
    missingok
    notifempty
    postrotate
        /usr/local/php/sbin/php-fpm -t >/dev/null 2>&1 || exit 0
        kill -USR2 $(cat /var/run/php-fpm.pid)
    endscript
}

避坑4：慢SQL关联trace_id的解析有坑。 我用awk解析慢日志时发现，# Time:行的时间是UTC格式，但PHP-FPM慢日志是服务器本地时间。两者相差8小时，直接join出来的全是错位数据。后来统一在分析脚本里做时区转换，才正确对上。

# 在awk里把UTC时间转成北京时间
# 原始: # Time: 2024-03-14T14:32:18.572304Z
# 目标: 2024-03-14 22:32:18
date -d "2024-03-14T14:32:18.572304Z" "+%Y-%m-%d %H:%M:%S" "+%Y-%m-%d %H:%M:%S"

总结

回看这次排障，真正花时间的不是加索引那几秒，而是确认"这条慢SQL是哪个接口的哪次请求触发的"。MySQL慢日志和PHP-FPM慢日志各管一段，不打通就永远在猜。trace_id把两边串起来后，一次grep就能定位到具体请求日志，再往上翻Nginx访问日志，找到用户、接口、参数，问题直接闭环。

这套双维度日志方案，我们没有引入任何新组件，只是改了配置和日志格式，效果是把慢SQL定位时间从小时级缩短到分钟级。

如果你们也在跟慢查询缠斗，按这个顺序做：先开慢日志（MySQL + PHP-FPM两个都要开）→ 统一trace_id → 分析脚本按时间窗口关联 → 建索引 → 告警接入。别一上来就上APM，那是后话。

最后一句：线上任何一次慢查询事故，都是日志体系不完善的锅。把日志留好，把trace_id串起来，很多问题不用等监控告警，你自己查日志就能提前发现。