一次订单导出卡死30秒的排查
2024年3月，运营在群里喊：订单导出页面点完一直转圈，30秒都出不来。
当时的环境：PHP 8.3 + Laravel 11 + MySQL 8.0.35，部署在K8s里，Nginx做网关。第一反应查PHP-FPM状态，正常，没有进程堆积。查Nginx access log，那个接口的响应时间确实是32.4秒，HTTP 200但页面就是白屏。
排查链路走到MySQL这层，打开了慢查询日志，发现一条SQL执行了1.2秒：
SELECT * FROM orders
WHERE status = 'paid'
ORDER BY created_at DESC
LIMIT 10;这个接口前后要查10次类似SQL，算下来就是12秒多。再加点别的逻辑，30秒没跑完很正常。
问题定位了。接下来就是两件事：怎么系统地拿慢查询日志，怎么把它改快。
两种慢查询日志方案对比
拿到慢SQL之后，我们需要一套能持续发现慢查询的机制，不能每次都等人喊卡。
| 对比项 | MySQL原生慢查询日志 | 应用层慢查询日志 |
|---|---|---|
| 定位层级 | DB层，记录所有超过阈值的SQL | PHP层，记录应用执行的慢SQL和慢请求 |
| SQL完整度 | 记录参数化前的原始SQL，包含绑定值 | 记录ORM生成的SQL，可能丢失绑定值 |
| 性能开销 | 低，MySQL内部直接写日志文件 | 中，每次查询都要做时间比较和日志写入 |
| 定位代码能力 | 弱，只能看到SQL，看不到调用栈 | 强，可以记录来源Controller/Job |
| 部署成本 | 改MySQL配置，重启生效 | 改PHP代码，发布上线 |
| 适合场景 | 产线排查、DBA日常巡检 | 开发环境、内部系统、复杂业务链路 |
两者不是替代关系。MySQL慢查询日志负责"面"，应用层日志负责"点"。我的做法是：产线开MySQL慢查询日志做全局扫描，应用层给核心接口加慢请求中间件做精确追踪。
方案一：MySQL慢查询日志的完整配置
第一步：开启慢查询日志
MySQL 8.0.35，修改my.cnf：
# /etc/my.cnf 追加以下配置
[mysqld]
slow_query_log = ON
slow_query_log_file = /var/log/mysql/mysql-slow.log
long_query_time = 0.5
log_queries_not_using_indexes = ON
min_examined_row_limit = 100参数说明：
long_query_time = 0.5：超过500毫秒的SQL都记录。生产环境建议从1秒开始，确认没问题后再调到0.5秒，避免日志量过大。log_queries_not_using_indexes：记录全表扫描的SQL，哪怕它执行时间不到阈值。min_examined_row_limit = 100：只记录扫描行数超过100行的，过滤掉小表全扫。
改完重启MySQL或动态开启：
# 不用重启，直接运行时开启
mysql -uroot -p -e "SET GLOBAL slow_query_log = 'ON';"
mysql -uroot -p -e "SET GLOBAL long_query_time = 0.5;"
mysql -uroot -p -e "SET GLOBAL log_queries_not_using_indexes = 'ON';"确认生效：
mysql -uroot -p -e "SHOW VARIABLES LIKE 'slow_query_log%';"
mysql -uroot -p -e "SHOW VARIABLES LIKE 'long_query_time%';"
mysql -uroot -p -e "SHOW VARIABLES LIKE 'log_queries_not_using_indexes%';"输出示例：
+---------------------+-----------------------------------+
| Variable_name | Value |
+---------------------+-----------------------------------+
| slow_query_log | ON |
| slow_query_log_file | /var/log/mysql/mysql-slow.log |
+---------------------+-----------------------------------+
| Variable_name | Value |
+---------------------+-----------------------------------+
| long_query_time | 0.500000 |
+---------------------+-----------------------------------+
| Variable_name | Value |
+---------------------+-----------------------------------+
| log_queries_not_using_indexes | ON |
+---------------------+-----------------------------------+第二步：生产环境日志采集
慢查询日志是文本文件，不会自动轮转。我写了一个cron脚本，每天凌晨切割归档，保留30天：
#!/bin/bash
# /usr/local/bin/rotate-slow-log.sh
# 每天凌晨1点执行：0 1 * * * /usr/local/bin/rotate-slow-log.sh
LOG_DIR="/var/log/mysql"
SLOW_LOG="${LOG_DIR}/mysql-slow.log"
YESTERDAY=$(date -d "yesterday" +%Y%m%d)
# 用mv切割日志，MySQL会继续往原路径写
mv ${SLOW_LOG} ${SLOW_LOG}.${YESTERDAY}
# 优雅刷新日志文件句柄
mysql -uroot -p'your_password' -e "FLUSH SLOW LOGS;"
# 只保留30天
find ${LOG_DIR} -name "mysql-slow.log.*" -mtime +30 -delete脚本放到crontab里：
0 1 * * * /usr/local/bin/rotate-slow-log.sh >> /var/log/rotate-slow-log.log 2>&1第三步：用pt-query-digest分析日志
mysqldumpslow是MySQL自带的工具，但功能太弱。我推荐pt-query-digest，Percona Toolkit里的神器。版本：Percona Toolkit 3.5.7。
安装（Ubuntu）：
apt-get install percona-toolkit -y分析慢查询日志：
pt-query-digest /var/log/mysql/mysql-slow.log > /tmp/slow-analysis.txt输出摘要：
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ============================= =============== ===== ====== ===== =====
# 1 0x1A2B3C4D5E6F7A8B9C0D1E2F3A4B5C6D 128.5231 72.3% 145 886.4ms 0.20 SELECT orders
# 2 0x3F4E5D6C7B8A9F0E1D2C3B4A5F6E7D8C9 18.2342 10.2% 32 569.8ms 0.40 SELECT users
# 3 0x5A6B7C8D9E0F1A2B3C4D5E6F7A8B9C0D1 8.1234 4.6% 12 676.9ms 0.10 SELECT order_items关键信息解读：
Response time：该SQL累计耗时和占比。第一条占了72.3%的总慢查询时间，优先搞它。Calls：执行次数。145次，说明是高频SQL。R/Call：平均每次886.4ms，远超阈值。
再看这条SQL的详细报告：
# Query 1: 0.71 QPS, 0.63x concurrency, ID 0x1A2B3C4D5E6F7A8B9C0D1E2F3A4B5C6D
# Time range: 2024-03-18T00:00:02 to 2024-03-18T23:59:58
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 57 145
# Exec time 1796s 2s 3s 886ms 2s 412ms 752ms
# Lock time 12 371ms 0 742us 22us 58us 46us 9us
# Rows sent 3 3.44k 0 30 24.28 28.20 7.06 24.28
# Rows examine 39 354.50k 1.25k 2.62k 2.45k 2.61k 116.11 2.39k
# Query size 10 127.00k 913 930 912.69 921.20 4.51 916.36
# String:
# Databases order_db
# Hosts 10.0.3.12 (99/145), 10.0.3.15 (46/145)
# Users php_app
# Query_time distribution
# 1us-10ms: 0
# 10ms-100ms: 0
# 100ms-1s: 12.41%
# 1s-10s: 87.59%
# Tables
# SHOW TABLE STATUS LIKE 'orders'\G
# SHOW CREATE TABLE `orders`\G
# EXPLAIN SELECT * FROM orders WHERE status = 'paid' ORDER BY created_at DESC LIMIT 10\G从Rows examine看，每次查询扫描了约2450行，但只返回24行。这不是典型的全表扫描，更像是status字段区分度太低，MySQL选择走索引扫描大量数据再排序。
方案二：应用层慢日志中间件
MySQL慢查询日志能定位到SQL，但定位不到代码。一次接口慢，可能是10条SQL叠加，每条都没超过阈值，但加起来超过1秒。应用层日志要解决这个问题。
Laravel 11监听慢查询
Laravel提供了DB::listen事件。我写了一个监听器，超过300ms的查询单独记录：
time < self::SLOW_QUERY_MS) {
return;
}
$sql = $event->sql;
$bindings = $event->bindings;
$time = $event->time;
$connection = $event->connectionName;
// 将绑定值填入SQL，方便直接复制执行
foreach ($bindings as $binding) {
if (is_numeric($binding)) {
$sql = preg_replace('/\?/', $binding, $sql, 1);
} else {
$sql = preg_replace('/\?/', "'{$binding}'", $sql, 1);
}
}
// 拿到调用来源
$traces = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS, 10);
$caller = 'unknown';
foreach ($traces as $trace) {
if (isset($trace['file']) && !str_contains($trace['file'], 'vendor/laravel')) {
$caller = basename($trace['file']) . ':' . $trace['line'];
break;
}
}
Log::channel('slow_query')->warning('Slow Query Detected', [
'sql' => $sql,
'time_ms' => $time,
'caller' => $caller,
'connection' => $connection,
'trace_id' => request()->header('X-Trace-ID', ''),
]);
}
}注册事件监听，在AppServiceProvider里：
handle($event);
});
}
}配置日志通道，config/logging.php里加一个独立文件：
[
'driver' => 'daily',
'path' => storage_path('logs/slow-query.log'),
'level' => 'warning',
'days' => 14,
],再给核心接口加个慢请求中间件
SQL是快了，但接口整体慢可能是外部HTTP调用或Redis拖后腿。这个中间件记录超过500ms的完整请求：
= self::SLOW_REQUEST_MS) {
Log::channel('slow_request')->warning('Slow Request Detected', [
'method' => $request->method(),
'uri' => $request->fullUrl(),
'duration_ms' => $duration,
'trace_id' => $request->header('X-Trace-ID', ''),
'auth_id' => $request->user()?->id,
]);
}
return $response;
}
}注册到app/Http/Kernel.php的api中间件组：
[
\App\Http\Middleware\RequestPerformanceMiddleware::class,
// 其他中间件...
],
];慢SQL调优实战：从1.2秒到8毫秒
拿日志里那条最慢的SQL开刀。
复现慢查询
-- SQL执行时间：1.2秒
-- 扫描行数：664,832行
-- 表数据量：约66万行
SELECT * FROM orders
WHERE status = 'paid'
ORDER BY created_at DESC
LIMIT 10;查看执行计划
EXPLAIN SELECT * FROM orders
WHERE status = 'paid'
ORDER BY created_at DESC
LIMIT 10\G输出：
id: 1
select_type: SIMPLE
table: orders
partitions: NULL
type: ALL
possible_keys: idx_status
key: NULL
key_len: NULL
ref: NULL
rows: 664832
filtered: 30.25
Extra: Using where; Using filesort
1 row in set, 1 warning (0.01 sec)问题很明显：
type: ALL：全表扫描，66万行全过一遍。Extra: Using filesort：文件排序，因为status索引只过滤了status，但ORDER BY的是另一个字段，导致MySQL要先把结果集加载到内存/磁盘临时表排序，再取前10行。
为什么走了索引还是慢？
orders表已经有了idx_status索引，但优化器算了一笔账：status='paid'这个条件能过滤约55%的行。对优化器来说，与其按索引逐行回表判断，不如直接全表扫描再排序来得快。
这里本质是status区分度太低。如果你用SHOW INDEX FROM orders看Cardinality，会发现idx_status的区分度只有2——就两个值：paid和unpaid。
创建复合索引
解决思路：让索引同时覆盖WHERE和ORDER BY两个条件。这样MySQL能在索引内部完成过滤和排序，不用filesort，也不用回表。
ALTER TABLE orders ADD INDEX idx_status_created_at (status, created_at DESC);DESC关键字在MySQL 8.0支持，让索引按created_at降序存储，正好匹配ORDER BY created_at DESC，连反向扫描都省了。
验证效果
重建执行计划：
EXPLAIN SELECT * FROM orders
WHERE status = 'paid'
ORDER BY created_at DESC
LIMIT 10\G输出：
id: 1
select_type: SIMPLE
table: orders
partitions: NULL
type: ref
possible_keys: idx_status_created_at
key: idx_status_created_at
key_len: 2
ref: const
rows: 10
filtered: 100.00
Extra: Backward index scan
1 row in set, 1 warning (0.01 sec)rows: 10，直接从66万降到10。MySQL知道status过滤后还是有很多行，但索引已经排好序了，从头按顺序扫10条就够。
性能对比
在MySQL 8.0.35下，用BENCHMARK和PROFILING对比优化前后：
-- 优化前
SET profiling = 1;
SELECT * FROM orders
WHERE status = 'paid'
ORDER BY created_at DESC
LIMIT 10;
SHOW PROFILE FOR QUERY 1;优化前Profile关键数据：
+----------------------+-----------+
| Status | Duration |
+----------------------+-----------+
| Sending data | 0.892412 |
| Sorting result | 0.312578 |
| statistics | 0.082134 |
| ... | ... |
| Total | 1.284215 |优化后：
SELECT * FROM orders
WHERE status = 'paid'
ORDER BY created_at DESC
LIMIT 10;
SHOW PROFILE FOR QUERY 2;优化后Profile关键数据：
+----------------------+-----------+
| Status | Duration |
+----------------------+-----------+
| Sending data | 0.007812 |
| statistics | 0.000412 |
| ... | ... |
| Total | 0.008312 |单条SQL：1.284秒 → 0.008秒，提升约160倍。
接口整体耗时对比
订单导出接口原来调用10次这条SQL（在循环里查订单明细），加上其他逻辑：
| 指标 | 优化前 | 优化后 | 提升 |
|---|---|---|---|
| 接口响应时间 | 980ms | 37ms | 26.5倍 |
| SQL总耗时 | 12.8s | 80ms | 160倍 |
| 扫描行数 | 664,832 | 10 | 66,483倍 |
| sort缓冲使用 | 32MB | 0 | -- |
压测数据
用Apache Bench压一下真实接口，ab -n 1000 -c 50，PHP 8.3 + Laravel 11环境：
# 优化前
ab -n 1000 -c 50 "https://api.example.com/orders/export?date=2024-03-18"
# 结果摘要：
# Requests per second: 24.18 [#/sec] (mean)
# Time per request: 2067.12 [ms] (mean)
# Percentage of requests served within a certain time (ms)
# 50% 1982
# 75% 2034
# 90% 2098
# 95% 2156
# 99% 2265# 优化后
ab -n 1000 -c 50 "https://api.example.com/orders/export?date=2024-03-18"
# 结果摘要：
# Requests per second: 642.38 [#/sec] (mean)
# Time per request: 77.84 [ms] (mean)
# Percentage of requests served within a certain time (ms)
# 50% 35
# 75% 41
# 90% 55
# 95% 68
# 99% 96QPS从24涨到642，TP99从2265ms降到96ms。
完整调优流程回顾
这套流程现在是我们团队的标准操作，跑一遍不超过30分钟：
# 1. 看慢查询日志里Top10 SQL
pt-query-digest /var/log/mysql/mysql-slow.log | head -80
# 2. 拿到慢SQL，先EXPLAIN看执行计划
mysql -uroot -p -e "EXPLAIN SELECT * FROM orders WHERE status='paid' ORDER BY created_at DESC LIMIT 10\G"
# 3. 确认索引情况
mysql -uroot -p -e "SHOW INDEX FROM orders;"
# 4. 加索引
mysql -uroot -p -e "ALTER TABLE orders ADD INDEX idx_status_created_at (status, created_at DESC);"
# 5. 再EXPLAIN确认走向新索引
mysql -uroot -p -e "EXPLAIN SELECT * FROM orders WHERE status='paid' ORDER BY created_at DESC LIMIT 10\G"
# 6. 压测确认接口耗时
ab -n 1000 -c 50 "https://api.example.com/orders/export?date=2024-03-18"避坑指南
这几个月折腾慢查询日志，踩了不少坑，列几个最典型的：
坑1：log_queries_not_using_indexes一开，磁盘瞬间爆满
把log_queries_not_using_indexes = ON配上long_query_time = 0.5，以为万无一失。结果第二天早上磁盘告警——2小时写了40GB日志。
原因：很多低区分度索引的查询（比如status字段只有两个值），优化器会全表扫，这些查询执行时间不长但被打进日志。当时有一个报表接口，每次跑批5万行全扫，直接刷爆。
解决办法：min_examined_row_limit = 100加上，扫描行数低于100的不记录。还有long_query_time先别设太低，从1秒开始。
坑2：mysqldumpslow的-t参数不是time
一开始用mysqldumpslow -t 10，以为取Top10耗时的SQL。实际效果：返回的是按次数排序的前10条，不是按时间排的。
看源码才知道，-t是"top n"，只是取前n条，不指定-s时默认按count排序。正确姿势：
# 按总耗时排序取Top10
mysqldumpslow -s at -t 10 /var/log/mysql/mysql-slow.log
# 按平均耗时排序取Top10
mysqldumpslow -s ar -t 10 /var/log/mysql/mysql-slow.log-s at是按平均查询时间排序，-s ar是按平均锁定时间排序。建议直接用pt-query-digest，它的排序逻辑更直观。
坑3：慢查询日志里的时间是完成时间，不是开始时间
有一次排查夜间慢SQL，日志里看到一条凌晨3点的慢查询。去看当时有没有Job在跑，发现没有。后来查binlog，发现那条SQL其实是晚上11点开始执行的，跑了4个小时才完成，写日志的时间是凌晨3点。
所以排查慢SQL时，要看Query_time和Lock_time，结合binlog确认真实开始时间，别被日志的写入时间误导。
坑4：服务器时钟漂移导致日志时间对不上
K8s里pod和宿主机时间戳可能不一致。有一次从慢查询日志看到一个查询在12:00:00执行，但业务高峰期在11:58-11:59，数据库监控也显示11:59有IO波峰。
对不上，排查了半小时发现是时钟漂移——NTP没同步。mysqld_slow_query_log记录的是系统时间，而业务监控用的是另一台机器时间。上线前先检查所有数据库节点的时间同步。
坑5：本地开发环境配置了慢查询日志，把sleep也算进去了
本地MySQL设了long_query_time = 0.1，发现有条SQL执行了200ms：SELECT SLEEP(1)。这是同事手动跑测试的SQL，不是应用发的。
不解决也不影响，但每天看日志会麻痹。给本地和产线分开配置，产线严格0.5秒，本地随意。
坑6：小心索引失效的三种情况
加上复合索引后，开发同事随手一个WHERE DATE(created_at) = '2024-03-18'就把索引废了——函数包裹索引列会导致索引失效。还有WHERE status LIKE '%paid%'这种前缀模糊匹配，也走不了索引。
EXPLAIN里的type字段很直观：ALL是全表扫，ref是普通索引查询，const是主键等值查询。上线前拿生产真实SQL跑一遍EXPLAIN，看到ALL再改SQL。
坑7：pt-query-digest不会按天自动分割日志
慢查询日志文件一大了，pt-query-digest分析起来非常慢，一个2GB日志跑了20分钟没出结果。后来发现它可以把分析结果按天切割：
# 按天分割并分析
pt-query-digest --output slowlog /var/log/mysql/mysql-slow.log --since 24h > /tmp/slow-today.txt但更推荐的做法：配合前面写的rotates脚本，每天归档一份，分析昨天的文件。
最后说一句
慢查询日志只是排查工具，真正解决问题的是理解索引和SQL的执行计划。每次看到慢SQL，别急着加索引，先EXPLAIN搞清楚它为什么慢——是全表扫、文件排序、还是临时表。搞清楚原因再动手，大部分慢查询一个复合索引就能解决。