周五晚上九点多,我正在家收拾东西,手机报警群连续弹了几条消息:线上订单列表接口 P99 飙到 4.2 秒,错误率虽然不高,但超时已经开始拖垮依赖它的下游服务。我打开监控面板,应用 CPU 只有 20%,Redis 命中率正常,GC 停顿也没异常。数据层连接池的活跃连接却一直满着,很明显,瓶颈在 MySQL 这边。
这种时候,我第一个要翻的东西就是 MySQL 的慢查询日志。做 Java 后端这些年,我越来越觉得慢查询日志是排查数据库问题的第一入口,它不是万能的,但能帮你在最短时间内把问题从"接口慢"缩小到"某条 SQL 慢",再配合执行计划定位到具体原因。这篇文章就围绕慢查询日志展开,从参数配置、日志解读、执行计划分析,到生产环境的运维边界和 Java 侧的配合,把我实际用过的路子完整梳理一遍。无论是刚接触 MySQL 的 Java 开发,还是在准备面试时被问到调优思路的候选人,都能从中拿到一套可以直接落地的排查方法。
1. 为什么要盯慢查询日志:一次线上接口超时的定位过程
1.1 排查思路的优先级排序
那晚的接口超时,如果按错误方向排查,可能折腾一小时都找不到根因。我的习惯是从最可能的原因开始排除:先看应用进程有没有假死,再确认外部依赖有没有抖动,接着查 Redis、MQ 这类中间件,最后落到数据库层。数据库层也分几步:先看连接数是否被打满,再确认是不是有锁等待,然后才轮到慢查询。
这里有个经验之谈:连接数打满往往不是原因,而是结果。大量请求拥堵在数据库连接池上排队,表象是"获取连接超时",本质可能是某几条 SQL 执行太慢,导致连接被长期占用。这个时候如果不去看慢查询日志,而是盲目调大连接池,只会让数据库更累,情况更糟。
MySQL 的日志体系里,跟排查相关的主要有四类:错误日志记录启动、运行、停止过程中的异常;binlog 用于主从复制和数据恢复;general log 会记录所有 SQL,生产环境几乎没人敢开,刷盘压力太大;慢查询日志则只记录执行时间超过阈值的 SQL。最后这个就是我定位问题最常用的工具——它精准、可控、成本相对低。
1.2 慢查询日志在整个排查链路里的位置
慢查询日志的价值在于,它把问题直接暴露在 SQL 粒度。你不需要依赖链路追踪,不需要在代码里埋点,只需要确认数据库开启了慢查询记录,然后在日志文件里搜索对应时间段的记录,往往一眼就能看到嫌疑对象。
那晚的情况就是这样。我登录服务器,打开 MySQL 慢查询日志,grep 出 21:00 到 21:05 之间的记录,发现同一条 SQL 出现了几十次:SELECT * FROM order_info WHERE user_id = ? ORDER BY create_time DESC LIMIT 20,平均执行时间 1.8 秒。看到这个结果,问题范围一下就收窄了:要么是索引没建对,要么是这条 SQL 本身走了全表扫描。后续的排查全部围绕这条 SQL 展开,不再瞎猜。
所以说,慢查询日志更像一个缩小包围圈的侦察兵。它不负责告诉你"为什么慢",但它能告诉你"是哪条 SQL 慢、慢到什么程度、执行时扫描了多少行",这些信息足以把问题定位到索引设计、SQL 写法或表结构这三类原因中去。
2. 慢查询日志的开关与阈值:参数细节和 5.7/8.0 的差异
2.1 三个核心参数
慢查询日志涉及的参数不多,最核心的是下面这三个,先用 SQL 看一下当前实例的状态:
SHOW VARIABLES LIKE 'slow_query_log'; SHOW VARIABLES LIKE 'long_query_time'; SHOW VARIABLES LIKE 'slow_query_log_file';slow_query_log:慢查询日志的总开关,ON 是打开,OFF 是关闭。MySQL 5.7 默认是 OFF,8.0 默认是 ON。long_query_time:慢查询阈值,单位秒,默认值是 10。也就是说,一条 SQL 如果执行时间超过 10 秒才会被记录。这个默认值在生产环境几乎没什么用,等真有 SQL 慢到 10 秒,业务早就超时到用户投诉了。我通常一上来就把它改成 1,也就是 1 秒。slow_query_log_file:日志文件路径。5.7 默认是主机名-slow.log,8.0 默认写到数据目录下的主机名-slow.log。生产环境建议显式指定一个独立路径,方便统一采集。
这里插一句题外话,之前有人问我 MySQL 5.7 的版本号为什么从 5.7.43 跳到 5.7.44,其实版本号就是按补丁顺序递增的,5.7.44 在 5.7.43 之后发布,只不过 5.7 系列已经进入维护期,两个版本间隔的时间会比较短。跟慢查询日志本身没什么关系,只是聊到版本时顺带说一句。
2.2 临时开启与会话级调试
修改参数有两种方式:一种是运行时动态修改,用SET GLOBAL或SET SESSION;另一种是改配置文件,重启后永久生效。
动态修改的命令是这样的:
SET GLOBAL slow_query_log = 'ON'; SET GLOBAL long_query_time = 1;注意,SET GLOBAL long_query_time只对之后新建的连接生效,不会影响已经存在的连接。所以你在命令行改了之后,最好重新开一个会话再查,或者等应用连接池建立新连接后才生效。这一点经常有人踩坑——改了参数,发现日志还在记录旧阈值的行为,就怀疑是不是没生效。
调试单条 SQL 时,我更喜欢用会话级参数。比如有一条 SQL 执行了 800 毫秒,还没到 1 秒的阈值,我想确认它到底有没有被记录,可以在当前会话里把阈值临时降为 0:
SET SESSION long_query_time = 0;这样当前会话里执行的所有 SQL 都会被记入慢查询日志,非常适合验证自己写的 SQL 是不是真的走了索引、执行计划有没有变化。用完记得会话结束就自动还原了,不影响其他连接。
2.3 永久配置与版本差异
如果希望数据库重启后依然保持配置,就得改配置文件。Linux 下是/etc/my.cnf,Windows 下是安装目录的my.ini,在[mysqld]段落里加:
[mysqld] slow_query_log = ON slow_query_log_file = /var/log/mysql/slow.log long_query_time = 1 log_queries_not_using_indexes = OFF关于 5.7 和 8.0 的差异,我实际用下来的感受是:5.7 默认关闭,需要手动开启;8.0 默认开启,但阈值还是 10 秒,实际意义有限。另外 8.0 默认把时间戳的时区记录为 UTC,查日志时容易对不上时间,建议在配置文件里加一行:
log_timestamps = SYSTEM让日志时间跟服务器本地时间保持一致,排查问题时能少绕一个弯。
3. 一行慢查询日志怎么读:字段含义与真实样本拆解
3.1 一条典型慢日志的逐段解析
开启慢查询日志之后,文件里每一条记录长这样(这是我在测试环境实际跑出来的一条数据):
# Time: 2025-11-15T21:03:22.188472+08:00 # User@Host: app_user[app_user] @ [10.0.0.12] Id: 123456 # Query_time: 1.824631 Lock_time: 0.000148 Rows_sent: 20 Rows_examined: 186432 use ecommerce; SET timestamp=1700053402; SELECT * FROM order_info WHERE user_id = 1234567 ORDER BY create_time DESC LIMIT 20;很多人拿到日志只盯 Query_time,这没错,但信息量太少了。我把每一行拆开说:
Time:SQL 执行的时刻,精确到微秒。结合log_timestamps = SYSTEM之后,这块跟应用日志的时间就能对齐了。User@Host:执行这条 SQL 的数据库账号和来源 IP。这一行很有用,如果多个应用共用一个 MySQL 实例,你可以通过它快速区分是哪个应用产生的慢 SQL。后面那个 Id 是线程 ID,可以跟SHOW PROCESSLIST对应。Query_time:MySQL 服务器端执行这条 SQL 的总耗时,包含解析、优化、执行等阶段。注意它不包含应用服务器到数据库之间的网络传输时间,所以经常出现数据库日志显示 0.5 秒,应用侧却感觉 1.5 秒的情况,剩下的时间可能花在应用拿结果、序列化、等待连接上了。Lock_time:锁等待时间。如果这个值明显偏大,说明 SQL 不是在"算",而是在"等"。常见于高并发下对同一行记录的更新,或者SELECT ... FOR UPDATE与普通查询之间的阻塞。Rows_sent:最终返回给客户端的行数。结果集只有 20 行,说明业务上要的数据量不大,问题不在这里。Rows_examined:执行过程中实际扫描的行数。18 万多行,这就是问题本尊——为了返回 20 条数据,扫描了 18 万行,典型的索引缺失或索引失效。
3.2 Query_time 和 Rows_examined 的关系是判断重点
我判断一条慢 SQL 属于什么类型问题,主要看 Query_time 和 Rows_examined 的组合。如果是扫描行数大、返回行数少,几乎可以断定是查询路径设计问题,要么没走索引,要么索引没覆盖到查询条件。这种情况在订单表、用户表、日志表这类数据量大的表上尤其常见。
还有一种情况是 Rows_examined 不算大,比如就扫了几千行,但 Query_time 依然很高。这时候要关注的就不单纯是索引了,可能是 MySQL 在排序、临时表、或者大字段传输上吃了亏。比如ORDER BY走了文件排序(filesort),或者查询中间产生了临时表,带的字段里有 TEXT、BLOB 类型导致排序成本飙升。这些在 EXPLAIN 的 Extra 列里能看到端倪。
另外,日志里的 SQL 文本是完整语句,带参数值。有人觉得写日志文件很占空间,其实它帮了大忙——你把参数值直接拿去 EXPLAIN 分析,或者复现问题,非常方便。但要注意,慢查询日志里的 SQL 文本是原样记录的,如果应用里用了 MyBatis,SQL 可能是这样式儿的占位符版本,参数值单独记录在SET timestamp附近的注释里,别搞混。
3.3 用 mysqldumpslow 快速聚合
日志文件积攒一段时间后,逐条看是不现实的。MySQL 自带了一个聚合工具叫mysqldumpslow,用法不难:
# 按平均执行时间排序,取前 10 条 mysqldumpslow -s t -t 10 /var/log/mysql/slow.log # 按出现次数排序,取前 10 条 mysqldumpslow -s c -t 10 /var/log/mysql/slow.log # 只看包含 order 的 SQL,按时间排序 mysqldumpslow -s t -g "order" /var/log/mysql/slow.log这个工具会做变量值的归一化:把数字替换成 N,把字符串替换成 S,所以同样一条 SQL 只有参数不同的多次执行,会被聚合成同一条记录。比如SELECT * FROM order_info WHERE user_id = 1234567和WHERE user_id = 7654321会合并成WHERE user_id = N统计。
实际用的过程中,-s t按平均耗时排序更适合找"单次最慢",-s c按次数排序更适合找"高频慢查询"。比如那晚的订单列表接口,按次数排完,SELECT * FROM order_info WHERE user_id = N ORDER BY create_time DESC LIMIT N排第一,出现 87 次,平均耗时 1.7 秒,这就是要优先处理的 SQL。
4. 顺着慢 SQL 挖根因:EXPLAIN 执行计划的关键列
4.1 type 与 key:先看这两列
拿到一条慢 SQL,我的惯例是立刻跑一次 EXPLAIN,看它到底怎么执行的。还是用那晚的 SQL 做例子:
EXPLAIN SELECT * FROM order_info WHERE user_id = 1234567 ORDER BY create_time DESC LIMIT 20;执行计划里最需要注意的是type和key两列。key显示这条 SQL 实际用到的索引,如果结果是 NULL,说明一张 18 万行的表在裸扫。type表示访问类型,从好到差大致是:
| type 值 | 含义 | 我的直观理解 |
|---|---|---|
| system/const | 主键或唯一索引等值查询,最多返回一行 | 直接命中目标,效率最高 |
| eq_ref | 被驱动表通过主键或唯一索引关联 | 多表 JOIN 时的理想情况 |
| ref | 通过普通索引等值匹配,返回多行 | 常用且健康的状态 |
| range | 索引范围扫描,比如 BETWEEN、IN、> < | 还能接受,但要注意范围大小 |
| index | 扫描整棵索引树 | 索引全扫,有时候比 ALL 好点,但也是问题 |
| ALL | 全表扫描 | 慢 SQL 的重灾区 |
那晚的 EXPLAIN 结果我记得很清楚:type 是 ALL,key 是 NULL,rows 显示 186432。这三项一连起来,结论就摆在眼前——user_id上没有可用的索引,MySQL 只能把整张表翻一遍。
4.2 我遇到过的三类索引失效
全表扫描是最好认的,但实际生产里还有三类更隐蔽的索引失效问题,慢查询日志里同样会暴露出来,我一个个说。
第一类是函数包裹索引列。比如WHERE DATE(create_time) = '2025-11-15',日子一长,表数据量一大,这个查询就会在慢查询日志里频繁出现。原因是 MySQL 对索引列做完函数计算之后,原来的索引顺序就失效了,只能全扫。优化办法是改成范围查询:WHERE create_time >= '2025-11-15 00:00:00' AND create_time < '2025-11-16 00:00:00'。
第二类是隐式类型转换。有个索引列是 VARCHAR 类型,比如手机号字段mobile,写条件时图省事传了个数字:WHERE mobile = 13800138000。MySQL 会把列值转成数字跟常量比较,索引就废了。改成一个字符串:WHERE mobile = '13800138000',执行计划立刻就不一样了。这类问题很容易被忽略,因为小数据量时看不出来,数据量一大就上慢查询日志。
第三类是 OR 条件导致索引失效。比如WHERE user_id = 123 OR status = 1,只要其中一个条件没有索引,整个查询就可能退化成全表扫描。建议拆成两个查询用 UNION 合并,或者给status也建上合适的索引。
4.3 优化后的验证方法
找到根因之后,不能改完就完事。我会重新执行 EXPLAIN 确认执行计划变了,再实际跑一遍 SQL 看耗时降了多少。这不是形式主义——有时候你以为加了索引,结果因为前缀长度、排序方向或者字符集不一致,索引压根没生效。
那晚我给order_info表加了联合索引(user_id, create_time),原因很简单:查询条件是等值的user_id,排序是create_time,这个联合索引既能精确定位用户的数据,又能让排序直接利用索引顺序,省掉 filesort。之后重新 EXPLAIN,type 从 ALL 变成了 ref,key 显示新索引名,rows 只剩 20 左右。再跑一次 SQL,执行时间从 1.8 秒降到 20 毫秒,接口 P99 也跟着掉下来了。
如果加了索引还是不理想,我会顺手看一眼 Extra 列有没有Using filesort或Using temporary。这两个词出现时,MySQL 在额外干活:排序如果没走索引,会把数据先放进内存或磁盘排序;Using temporary更是直接说明它建了临时表。这类 SQL 即使没到慢查询阈值,也是潜在的性能隐患,值得提前优化。
5. 慢查询日志的运维边界:别开着开关就撒手
5.1 日志写入的代价
慢查询日志既然这么好用,是不是干脆一直开着不关?我的答案是:开可以,但别开得太放任。
日志写入是有 IO 代价的。尤其是把long_query_time设得很低,比如 0.1 秒,再加上log_queries_not_using_indexes = ON,慢查询日志可能每分钟写几万行,磁盘 IO 被日志刷盘占掉不少,反而影响正常业务。我见过一个案例,某团队把阈值设成 0,日志文件一天涨了 20G,最后把数据盘写满了,数据库直接只读,事故比原来的慢查询还严重。
这里要区分一个概念:log_queries_not_using_indexes记录的是"没走索引"的 SQL,不是"慢"的 SQL。有些小表只有几百行,全表扫描也就一两毫秒,本来不是问题,但开着这个参数就会把它们全记进日志,制造大量噪音,把真正需要关注的慢 SQL 淹没掉。
5.2 文件轮转和空间控制
日志文件无限增长是另一个必须提前处理的问题。MySQL 不会自动切割慢查询日志文件,需要外部工具或者手动轮转。
我常用的手动方式是这样的:
# 1. 重命名当前日志文件 mv /var/log/mysql/slow.log /var/log/mysql/slow.log.20251115 # 2. 让 MySQL 重新生成新的 slow.log mysql -e "FLUSH SLOW LOGS;"FLUSH SLOW LOGS会让 MySQL 关闭当前日志文件,重新按slow_query_log_file指定的路径创建新文件,这样旧文件就可以归档或删除了。如果你的服务器装了 logrotate,也可以直接配一条规则,按天或按大小轮转,原理是一样的。
实际操作中我还会配一个脚本,每天检查日志文件大小,超过 500M 就轮转一次,保留最近 7 天的归档。这个数字不是绝对的,主要看你实例的慢查询数量,但原则是明确的:日志文件不能无限膨胀,归档要有保留策略。
5.3 参数组合的建议
经过多次线上折腾,我目前比较推荐的组合是这样的:
| 参数 | 测试环境 | 生产环境 |
|---|---|---|
| slow_query_log | ON | ON |
| long_query_time | 0.2 | 1 |
| log_queries_not_using_indexes | ON | OFF |
| min_examined_row_limit | 0 | 1000 |
| log_slow_admin_statements | OFF | OFF |
log_slow_admin_statements默认是不记录 ALTER TABLE 这类管理语句的,我建议保持关闭。DDL 本来就慢,如果也被记进慢查询日志,会干扰对业务 SQL 的分析。
min_examined_row_limit是另一个有用的过滤条件,表示扫描行数少于多少的不记录。生产环境我常设成 1000,这样即使某些 SQL 没走索引,只要扫描行数极少,也不会产生日志噪音。它比单纯依赖执行时间更能过滤掉无意义记录,因为扫描行数少的时候,即使因为某种原因耗时略高,影响面也有限。
生产环境还有一个不太起眼的注意点:查询慢查询日志内容时,建议用tail或less,别直接cat。日志文件大起来之后,cat会把整个文件读进内存,本身就是一个不小的 IO 操作。我吃过多线程grep大日志拖慢数据库的亏,从那之后凡是看日志,先ls -lh看大小,再决定怎么读。
6. 慢查询治理不是数据库单方面的事:Java 侧怎么配合
6.1 连接池与 ORM 层面的辅助
慢查询日志是数据库视角的工具,但治理慢查询不能只盯着数据库看。我在 Java 项目的日常维护里,还会从应用侧做几件事来配合。
第一是连接池的慢 SQL 统计。我们项目用的是 Druid,它自带 SQL 监控。在连接池配置里开启StatFilter之后,控制台上能看到每个 SQL 的执行次数、总耗时、最大耗时,还能设置慢 SQL 阈值做标记。这相当于在应用侧又多了一层慢查询感知,比起翻数据库日志更实时。如果你的项目用 HikariCP,它没有内置慢 SQL 统计,那就需要自己在 MyBatis 拦截器或者 Spring AOP 里做一层耗时统计。拦截的方法也很简单:记录@Around切面里 DAO 方法的耗时,超过 500 毫秒就打印告警日志,带上参数和 SQL。
第二是 ORM 框架的 SQL 输出。MyBatis 的mybatis.configuration.log-impl设为标准日志输出,可以打印出真实执行的 SQL 和参数。结合慢查询日志里那条 SQL 的文本,能在应用代码里快速定位到对应的 Mapper 方法。这里有个小经验:生产环境不要一直开着 SQL 全量打印,IO 和日志量都受不了,可以用一个开关控制,排查时开半小时,查完关掉。
6.2 索引设计与 SQL 写法上的三个高频坑
慢查询日志看得多了,你会发现出问题的 SQL 翻来覆去就是那几类。Java 后端写 SQL 时,有三个高频坑值得提前规避。
第一个是SELECT *。Java 代码里图省事写了select *,返回到应用层却发现只需要其中两三个字段。不仅网络传输多,还断了覆盖索引的可能性。覆盖索引是优化查询的利器——如果索引本身包含了查询需要的所有列,MySQL 就不用回表,直接扫描索引就返回结果。一旦select *,回表几乎不可避免。
第二个是深分页。LIMIT 100000, 20这类写法,看着是只要 20 条,MySQL 实际要把前 10 万行全扫出来再丢掉。慢查询日志里这类 SQL 特别多。我的优化办法是延迟关联:先通过覆盖索引查出主键,再用主键关联回原表取完整行。或者改造成基于游标的分页,用WHERE id > last_max_id ORDER BY id LIMIT 20,前提是业务允许这种分页方式。
第三个是联合索引的字段顺序。建索引时把等值条件字段放前面,排序字段放后面,才可能同时服务过滤和排序。字段顺序反了,order_info表那个例子就是现成反面教材——只给user_id建了单列索引,排序还是要额外 filesort。索引不是越多越好,但每个常用查询路径,至少该有一个能"接住"它的联合索引。
6.3 把慢查询分析变成日常巡检
最后聊一个方法论层面的经验:慢查询日志不应该是出了事故才去翻的东西。我现在的习惯是,每周固定一次从慢查询日志里导出数据,按出现次数和平均耗时排序,看看有没有新冒出来的慢 SQL。很多问题在变成严重事故之前,早就在日志里露出了苗头——某个接口的 SQL 执行时间从 50 毫秒慢慢涨到 800 毫秒,期间可能持续了两周,如果没人看日志,就会一直被忽视直到触发告警。
配合这个习惯,我还会把 mysqldumpslow 的结果跟应用发布记录做对比。很多慢查询是发版后引入的:某个同事改了一条 SQL 的写法,或者一个上线的新功能带了低效的查询。如果巡检日志的时机刚好卡在发版之后,很容易就能定位到是哪次变更引入了性能退化。
MySQL 的慢查询日志并不复杂,核心就是开关、阈值、文件位置三个参数,加一个 mysqldumpslow 聚合工具。但它串联起来的排查链路是完整的:从日志发现慢 SQL,到 EXPLAIN 分析执行计划,再到索引设计和 SQL 改写,最后验证效果并沉淀为巡检项。这套流程我用了很多年,每次遇到性能问题都靠它快速收窄范围。如果你现在连慢查询日志都还没打开,我建议今天就先按文章里的参数组合配起来,等哪天线上真出问题的时候,你会发现这个开关救了大忙。