那天凌晨1点的CPU告警
2024年3月,我值班。凌晨1:23,监控弹窗:MySQL CPU使用率98.7%,持续5分钟。登录服务器一看,慢查询日志文件已经涨到2.8GB,每分钟新增200MB。数据库的long_query_time配的是2秒,按理说不该这么夸张。
查出来是一条诡异的UPDATE语句,没走索引,每次更新扫了全表300万行,耗时2.1秒。因为走的业务定时任务,每小时跑一轮,一轮触发上千次。
问题解决后我复盘:慢查询日志是MySQL在记,但怎么从几万条日志里快速定位问题SQL,工具选型很重要。这文章就讲两条最实用的路:mysqldumpslow(命令行)和MySQL Workbench Performance Reports(图形化)。两条路我都跑过,各自有坑。
问题:慢查询日志有,但看不出问题
先交代环境:MySQL 8.0.35,CentOS 7.9,32核64G,业务库300万行订单表。慢查询日志配置:
# /etc/my.cnf
[mysqld]
slow_query_log = 1
long_query_time = 2
slow_query_log_file = /data/mysql/slow-query.log
log_queries_not_using_indexes = 1
log_timestamps = SYSTEM
日志有了,但当你真的打开这个文件,会发现完全没法看。几万条SQL,孰轻孰重你不知道,谁该先优化你不知道,哪些是同类SQL你也看不出来——因为它们只有参数不同,文本长得不一样。
这时候需要工具归类、聚合、排序。市面上常用的三种方案:
方案A:mysqldumpslow —— 系统自带,够用
MySQL自带的日志分析工具,随安装包一起发布,不需要额外装任何东西。核心能力是把相似的SQL归一化,比如WHERE user_id = 123和WHERE user_id = 456会被统一成WHERE user_id = N,然后按总耗时、平均耗时、执行次数排序。
优点:零依赖,一条命令出结果;输出格式紧凑;可以配合awk/uniq做二次加工。
缺点:丑,不直观,没有图表;看不到SQL对应表的索引状态;需要人工把高频SQL再粘到EXPLAIN里看执行计划。
方案B:MySQL Workbench —— 可视化,适合快速定位
MySQL官方GUI客户端,8.0.36版本。它的Performance Reports面板从performance_schema拿数据,把TOP SQL、执行次数、平均耗时、CPU消耗直接画成图,点击一条SQL可以直接跳到EXPLAIN。
优点:视觉冲击强,10秒内能锁定最耗时的SQL;可以直接测执行计划;适合不熟悉命令行的同学。
缺点:要装GUI客户端,远程连接需要开3306端口或SSH隧道;依赖performance_schema(MySQL 5.7+默认开,5.6要手动开);Workbench拿不到慢查询日志里但performance_schema里没有的历史数据。
方案C:pt-query-digest —— 功能最强,但部署维护成本高
Percona Toolkit里的神器,能分析慢查询日志、通用日志、Binlog,输出非常详细的报告,还能把分析结果存入数据库。但对大多数场景,杀鸡用牛刀。而且它用Perl写的,记得装一堆依赖,处理超大规模日志时内存吃紧。
别急着上最重的方案。我建议:先mysqldumpslow快速拿出TOP 10,再用Workbench对TOP SQL做执行计划分析。两条腿走路。
完整流程:从日志到索引优化
Step 1:开启慢查询日志(如果还没开)
生产环境建议直接改my.cnf并重启,保证永久生效。如果你不想重启,临时开也可以:
# 临时开启(重启MySQL后失效)
mysql -uroot -p
# 注意:下述都是SET GLOBAL,只影响新连接
SET GLOBAL slow_query_log = 'ON';
SET GLOBAL long_query_time = 1; # 超过1秒记录
SET GLOBAL log_queries_not_using_indexes = 'OFF'; # 千万别开,见避坑
SET GLOBAL slow_query_log_file = '/data/mysql/slow-query.log';
SET GLOBAL log_timestamps = 'SYSTEM';
改完确认生效:
SHOW VARIABLES LIKE 'slow_query_log';
SHOW VARIABLES LIKE 'long_query_time';
SHOW VARIABLES LIKE 'slow_query_log_file';
Step 2:造一个典型慢查询做测试
为了演示,我复制了一张线上订单表结构,灌了300万行数据。表结构如下:
CREATE DATABASE demo_db DEFAULT CHARACTER SET utf8mb4;
USE demo_db;
CREATE TABLE `t_order` (
`id` INT UNSIGNED AUTO_INCREMENT PRIMARY KEY,
`order_no` VARCHAR(64) NOT NULL,
`user_id` INT UNSIGNED NOT NULL,
`amount` DECIMAL(10,2) NOT NULL,
`status` TINYINT NOT NULL DEFAULT 0,
`created_at` DATETIME NOT NULL,
KEY `idx_order_no` (`order_no`)
) ENGINE=InnoDB;
注意:此时只有主键和order_no索引,没有user_id相关索引。于是这条业务查询就成了一条典型的全表扫描:
-- 模拟业务:查某个用户某个状态下的订单,按时间倒序
SELECT id, order_no, amount, created_at
FROM t_order
WHERE user_id = 123456 AND status = 1
ORDER BY created_at DESC
LIMIT 20;
Step 3:用mysqldumpslow做快速统计
让上面这条SQL跑几次,再跑一次mysqldumpslow:
# -s t 按总耗时排序,-t 10 取top10,-a 不把数字抽象成N
mysqldumpslow -s t -t 10 -a /data/mysql/slow-query.log
输出长这样:
Reading mysql slow query log from /data/mysql/slow-query.log
Count: 3 Time=2.10s (6.30s) Lock=0.00s (0.00s) Rows=20.0 (60),
SELECT id, order_no, amount, created_at
FROM t_order
WHERE user_id = 123456 AND status = 1
ORDER BY created_at DESC
LIMIT 20
一眼就能看出:这条SQL执行了3次,平均2.1秒。但它不告诉你为什么慢,下一步得看执行计划。
Step 4:EXPLAIN看执行计划
把SQL复制出来,前面加EXPLAIN:
EXPLAIN SELECT id, order_no, amount, created_at
FROM t_order
WHERE user_id = 123456 AND status = 1
ORDER BY created_at DESC
LIMIT 20\G
输出:
id: 1
select_type: SIMPLE
table: t_order
partitions: NULL
type: ALL
possible_keys: NULL
key: NULL
key_len: NULL
ref: NULL
rows: 2998453
filtered: 1.00
Extra: Using where; Using filesort
type: ALL是全表扫描,rows: 2998453表示扫描了300万行,Extra: Using filesort说明排序也没用上索引。这就是慢的原因。
Step 5:用Workbench对同一条SQL做可视化分析
Workbench的操作路径:
- 打开MySQL Workbench 8.0.36,连接目标实例(注意别用localhost,连远程用SSH隧道或直接IP);
- 左侧Navigator → Performance → Dashboard,先看整体负载;
- 点Performance Reports → Top SQL,能看到按总耗时排序的SQL列表;
- 找到目标SQL,右键 → Explain Current Statement,直接出执行计划图形。
等价于你在命令行敲EXPLAIN,但Workbench把执行计划画成带箭头的流程图,哪张表先读、走了哪个索引、扫描了多少行,一眼get。
除了Top SQL,Performance Reports里还有几个实用视图:Global Wait Events看等待事件(IO等待、锁等待),InnoDB I/O看磁盘读写。排查那种「SQL看着不慢但整个库卡」的问题,这两个视图比Top SQL还管用。
Workbench的底层数据来源是performance_schema,你可以直接查,效果一样:
-- 查看执行次数最多的TOP 10 SQL
SELECT
DIGEST_TEXT AS query,
COUNT_STAR AS exec_count,
ROUND(AVG_TIMER_WAIT / 1000000000, 2) AS avg_time_ms,
ROUND(SUM_TIMER_WAIT / 1000000000, 2) AS total_time_ms,
SUM_ROWS_EXAMINED AS rows_examined
FROM performance_schema.events_statements_summary_by_digest
ORDER BY SUM_TIMER_WAIT DESC
LIMIT 10;
Step 6:对症下药——加联合索引
这个查询的过滤条件是user_id + status,排序条件是created_at。最合适的索引:
ALTER TABLE t_order
ADD INDEX idx_user_status_created (user_id, status, created_at);
加索引后再次EXPLAIN:
EXPLAIN SELECT id, order_no, amount, created_at
FROM t_order
WHERE user_id = 123456 AND status = 1
ORDER BY created_at DESC
LIMIT 20\G
id: 1
select_type: SIMPLE
table: t_order
partitions: NULL
type: ref
possible_keys: idx_user_status_created
key: idx_user_status_created
key_len: 6
ref: const,const
rows: 148
filtered: 100.00
Extra: Using index condition
type: ref,扫描行数从300万降到148,Using filesort消失了。这就对了。
Step 7:自动化——用脚本定期生成慢查询报告
生产环境不能总靠人肉登录服务器执行命令。我写了一个Node.js脚本,每天凌晨跑一次,把慢查询日志分析结果推送到企业微信。核心逻辑不复杂,就是用正则把日志里的结构化信息抽出来:
// analyze-slowlog.js —— Node.js 18.16.0
// 用法: node analyze-slowlog.js /data/mysql/slow-query.log
const fs = require('fs');
const filePath = process.argv[2];
const content = fs.readFileSync(filePath, 'utf-8');
// 慢查询日志条目格式:
// # Time: 2024-03-15T01:23:45.123456Z
// # User@Host: root[root] @ localhost [127.0.0.1]
// # Query_time: 2.100000 Lock_time: 0.000000 Rows_sent: 20 Rows_examined: 2998453
// SET timestamp=1710465825;
// SELECT ...
const entries = content.split(/# Time:/).filter(Boolean).map(block => {
const timeMatch = block.match(/^[\d\-T:\.]+Z/m);
const queryTimeMatch = block.match(/Query_time: ([\d\.]+)/);
const rowsExaminedMatch = block.match(/Rows_examined: (\d+)/);
const sqlMatch = block.match(/SET timestamp=\d+;\n(.+?)(?=\n# |$)/s);
if (!timeMatch || !queryTimeMatch) return null;
return {
time: timeMatch[0],
queryTime: parseFloat(queryTimeMatch[1]),
rowsExamined: rowsExaminedMatch ? parseInt(rowsExaminedMatch[1]) : 0,
sql: sqlMatch ? sqlMatch[1].trim().slice(0, 500) : '',
};
}).filter(Boolean);
// 按执行耗时排序,取Top 20
const topSlow = entries
.filter(e => e.queryTime > 1)
.sort((a, b) => b.queryTime - a.queryTime)
.slice(0, 20);
console.log(`共解析 ${entries.length} 条慢查询,Top 5:`);
topSlow.slice(0, 5).forEach((e, i) => {
console.log(`${i + 1}. [${e.queryTime}s, rows=${e.rowsExamined}] ${e.sql.slice(0, 120)}`);
});
// 这里可以接企业微信/钉钉机器人推送
// const webhook = 'https://qyapi.weixin.qq.com/cgi-bin/webhook/send?key=xxx';
// fetch(webhook, { method: 'POST', body: JSON.stringify({ msgtype: 'text', text: { content: report } }) });
效果数据:优化前后对比
直接上数据,同一台机器,同一张300万行的表,同一套业务流量。
| 指标 | 优化前 | 优化后 | 提升 |
|---|---|---|---|
| SQL平均耗时 | 2.10s | 0.032s | 65倍 |
| SQL p99耗时 | 3.80s | 0.110s | 34倍 |
| 扫描行数 | 2,998,453 | 148 | 20259倍 |
| EXPLAIN type | ALL | ref | — |
| Extra | Using filesort | Using index condition | — |
| 数据库CPU使用率 | 98.7% | 12.3% | — |
| 每小时慢查询条数 | 约1200 | 约2~3 | 400倍 |
| 从开始排查到定位SQL | — | 不到3分钟(Workbench) | — |
业务侧的收益:那条定时任务原来跑35分钟,优化后40秒跑完。用户端接口原来偶尔卡顿,优化后完全稳定。
慢查询日志的工作原理(搞懂才能避坑)
慢查询日志不是「轮询检测所有SQL」,而是每个SQL执行完以后,由MySQL Server层判断执行时长是否超过long_query_time,超过就写入日志。这里有几个关键点:
- 判断时机是「执行完」,不是「执行中」。一条卡了12秒还没结束的SQL,要等它结束才会写日志。所以慢查询日志并不能实时反映正在跑的慢SQL,要实时监控得用performance_schema + sys.session或SHOW PROCESSLIST。
long_query_time精确到微秒,MySQL 5.1之后支持小数,比如0.5表示500ms。log_queries_not_using_indexes = ON会导致所有没走索引的查询都被记录,无论执行多快。这个开关很容易把慢查询日志撑爆,生产环境默认关。min_examined_row_limit这个变量很隐蔽。如果设置大于0,只有扫描行数超过阈值的SQL才会记入日志。它和long_query_time是「或」的关系:满足任意一个就会记录。- 慢查询日志文件写操作是每个慢SQL执行完同步追加,性能开销在0.1%以内,可以忽略。但日志量爆炸会导致磁盘IO吃紧,这是真实踩过的坑。
EXPLAIN关键字段速查
分析慢查询绕不开EXPLAIN,这里把最重要的字段说清楚:
| 字段 | 含义 | 重点关注 |
|---|---|---|
| type | 访问类型 | ALL=全表扫描,index=全索引扫描,range=索引范围扫描,ref=非唯一索引等值,const/eq_ref=唯一索引等值。性能从差到好:ALL < index < range < ref < eq_ref < const |
| key | 实际使用的索引 | NULL表示没走索引,必须查原因 |
| rows | 预估扫描行数 | 数值越大越危险。和实际行数差异过大说明统计信息过期,跑一下ANALYZE TABLE |
| Extra | 附加信息 | Using filesort=排序没用索引,Using temporary=用了临时表,Using index=覆盖索引。前两个优先优化 |
回到加索引这个事。联合索引(user_id, status, created_at)能同时优化过滤和排序,核心是索引最左前缀原则和B+树叶子节点有序性。
联合索引在B+树里先按第一个字段排序,字段相同再按第二个,依次类推。查询条件里user_id = 123456 AND status = 1正好命中前两列,等值匹配可以直接定位到那一小段数据。而created_at作为索引第三列,在固定user_id和status下天然有序,ORDER BY created_at DESC直接反向扫描就行,不需要额外排序。
Workbench连接与performance_schema的坑
Workbench好用是好用,但部署连接失败是家常便饭。我踩过的几类坑:
- 远程连接被防火墙挡了。云服务器安全组只放行80/443,3306没开。临时开3306还要限制来源IP,千万别搞成0.0.0.0/0。最好用SSH隧道:在Workbench的Connection → SSH Tunnel里配跳板机。
- performance_schema统计信息不准。MySQL 5.6默认关闭,5.7+默认开启。如果你看到Performance Reports里全空白,先执行
SHOW VARIABLES LIKE 'performance_schema';确认是ON。 - Workbench连接时「Server Status」显示乱码或者连不上,优先看MySQL错误日志
/var/log/mysqld.log,大部分原因是认证插件问题。MySQL 8.0默认用caching_sha2_password,老版本Workbench连不上,升级Workbench到8.0.36以上。 - events_statements_summary_by_digest表会在MySQL重启后清零,历史数据不会永久保留。
避坑指南(亲测有效)
1. 别在生产环境乱开log_queries_not_using_indexes
我干过这事。有一天想看看哪些查询没走索引,直接把log_queries_not_using_indexes设为ON。结果10分钟,慢查询日志从200MB涨到2.3GB。全库所有没走索引的小查询全被记下来了,有些查询执行只要0.01秒也被记录。磁盘告警,最后只能紧急关掉删日志。这个开关只建议在测试环境开。
2. long_query_time别设成0
设成0=记录所有查询,和坑1效果一样,日志爆炸。建议生产先用2秒,优化一轮后再调到1秒,最后0.5秒,循序渐进。
3. 慢查询日志时间戳默认是UTC,不是北京时间
MySQL 5.7.2+的log_timestamps默认是UTC。有一次凌晨排查问题,看到日志里最后一条慢查询是下午4点,以为慢查询已经停止了,实际上只是时区差8小时。设置log_timestamps = SYSTEM解决,或者你在看日志时心里加8小时。
4. mysqldumpslow默认会把数字抽象成N,真实值看不到
默认输出WHERE user_id = N AND status = N,你想知道具体是哪个user_id触发的慢查询,得加-a参数(不抽象数字),或者在慢查询日志里grep具体SQL。血泪教训:不加-a,你看到的报告除了SQL模板,什么都没有,没法精确定位业务方。
5. Workbench的EXPLAIN不能直接对UPDATE语句执行
Workbench里选中UPDATE语句点Explain,会报语法错误。正确做法:把UPDATE改成同条件的SELECT先看执行计划,或者用EXPLAIN UPDATE ...(MySQL 8.0支持),但Workbench图形界面对非SELECT的EXPLAIN支持不友好。命令行EXPLAIN UPDATE完全没问题。
6. 加了索引不生效——字符集和排序规则不一致
联表查询时两张表的关联字段如果字符集不同(utf8mb4 vs latin1),索引直接失效,因为MySQL必须在比较前做隐式转换。保证关联字段的字符集和collation完全一致。另外字段类型不同(INT vs VARCHAR)也会让索引失效。
7. pt-query-digest处理超大日志会OOM
2GB以上的慢查询日志,直接跑pt-query-digest,大概率内存吃满被OOM Killer干掉。解决办法是先按时间切分日志,或者用--limit限制处理行数。我后面直接改成自己写Node脚本了,更可控。
最后:这工具我还会继续用
mysqldumpslow仍然是我接手的每台MySQL服务器的第一排查工具,因为它够快、够稳定、随装随用。Workbench则是我做深度分析时的主力,看执行计划和全局等待事件它确实方便。
但别把过多精力放在工具本身。慢查询优化的核心仍然是:索引、索引、索引。工具只负责帮你把问题SQL从海量日志里捞出来。