做后端开发和数据库运维这些年,我最怕听到的一句话就是“接口突然变慢了”。页面转圈、接口超时、数据库CPU飙高,一顿排查下来往往无从下手。如果你也遇到过这种场景,我建议你先把目光投向一个最基础也最实用的工具——MySql慢查询日志(慢日志)。它就像数据库的黑匣子,会把每一条执行时间超过阈值的SQL原原本本记录下来,告诉你是哪条语句拖慢了整体性能。
这篇文章不聊空泛的理论,直接从实际运维视角出发,讲清楚慢查询日志的原理、开启方式、日志解读、分析工具和真实故障案例,最后附上我踩坑多年的经验总结。无论你是刚接触MySQL的开发者,还是已经在生产环境里摸爬滚打的DBA,这篇文章都能帮你把慢查询日志真正用起来。
1. 慢查询日志是什么:数据库性能问题的第一现场
1.1 工作原理:日志是怎么把慢SQL“抓”出来的
慢查询日志的机制并不复杂。MySQL在执行每一条SQL时,都会记录真实的执行时间。当这条SQL的执行时间超过了我们设定的阈值(默认是10秒),MySQL就会把这条SQL连同执行时间、锁等待时间、扫描行数等信息,原样写入到慢查询日志文件中。
这个过程是MySQL Server层完成的,不需要额外的插件,也不会影响正常的业务逻辑。你可以把它理解成家里装了一个智能电表,平时不会打扰你,但一旦某个电器的功率异常超标,它就会自动记录下来,提醒你去检查到底是哪台设备出了问题。
核心涉及三个变量:
slow_query_log:慢查询日志的总开关,值为ON或OFF。long_query_time:执行时间阈值,单位是秒,支持小数,比如0.5就代表500毫秒。slow_query_log_file:日志文件的存放路径。
在MySQL 5.7及以上版本中,这三个参数都可以在线动态修改。这也是它比很多外部监控工具更灵活的地方——发现问题随时可以打开,不需要重启数据库。
1.2 为什么慢查询日志是性能优化的起点
我见过不少开发同学,上来就讨论索引怎么建、SQL怎么改写,但问起“到底是哪条SQL慢”,却一脸茫然。这就好比你去看病,还没做检查就让医生开药,完全是在碰运气。
慢查询日志的价值就在于它提供了可量化的证据。它不只是告诉你“有一条SQL很慢”,更关键的是告诉你三个信息:这SQL在哪台客户端上执行的、执行了多久、扫描了多少行数据。有了这些原始线索,后续的索引优化、SQL改写才能有的放矢。
而且,慢查询日志暴露的问题面非常广。它不仅能反映索引缺失这类常见问题,还能暴露锁等待(Lock_time很大)、排序性能差(Order by导致文件排序)、深分页(limit偏移量过大)、隐式类型转换导致索引失效等一堆隐蔽问题。可以说,慢查询日志是绝大多数MySQL性能调优的起点,没有它,后面所有的工作都像是盲人摸象。
2. 开启慢查询日志:参数配置与三种开启方式
2.1 核心参数逐一说明
先把涉及慢查询日志的关键参数完整过一遍。除了上面提到的三个基础参数,还有几个辅助参数在实践中非常重要:
| 参数名 | 默认值 | 作用说明 |
|---|---|---|
slow_query_log | OFF | 总开关,ON开启,OFF关闭 |
long_query_time | 10 | 执行时间阈值,单位秒,超过才记录 |
slow_query_log_file | 主机名-slow.log | 日志存储路径和文件名 |
log_queries_not_using_indexes | OFF | 记录所有没走索引的SQL,哪怕执行时间没超阈值 |
log_slow_admin_statements | OFF | 记录ALTER TABLE、ANALYZE TABLE等管理语句 |
min_examined_row_limit | 0 | 扫描行数小于该值的SQL不记录,过滤小查询噪音 |
这里重点说下log_queries_not_using_indexes。我建议在开发环境打开这个参数,它可以帮你暴露出大量“跑得不算慢但根本没走索引”的SQL。这些SQL单次执行也许只花几十毫秒,但在高并发场景下,全表扫描带来的IO和CPU开销会被成倍放大,最终拖垮整个数据库。
需要特别提醒的是,这个参数在生产环境要慎开。如果业务里确实存在无法避免的全表扫描SQL(比如某些统计报表查询),日志文件会涨得飞快。我的经验是先短期打开观测一天,分析完再关掉。
2.2 临时开启与永久开启:两种方式各有利弊
第一种:临时开启(在线生效,重启失效)
-- 查看当前状态 SHOW VARIABLES LIKE 'slow_query_log'; SHOW VARIABLES LIKE 'long_query_time'; SHOW VARIABLES LIKE 'slow_query_log_file'; -- 开启慢查询日志 SET GLOBAL slow_query_log = 'ON'; -- 设置阈值,单位秒 SET GLOBAL long_query_time = 1; -- 设置日志文件路径(注意:MySQL服务账号需要对目录有写权限) SET GLOBAL slow_query_log_file = '/data/mysql/logs/slow.log'; -- 查看修改后是否生效 SHOW VARIABLES LIKE 'slow_query_log';注意,SET GLOBAL方式修改的是全局变量,对新的连接才生效,已经存在的会话仍会沿用旧参数。这一点经常有人踩坑——改完参数后,当前命令行窗口去查询还显示旧值,让人误以为没改成功。解决办法是重新连接一次,再执行SHOW VARIABLES确认。
第二种:永久开启(写入配置文件)
临时开启这种方式,数据库一重启就丢了。生产环境必须把配置写入配置文件,让MySQL每次启动都自动加载。
在Linux下编辑/etc/my.cnf,在[mysqld]段落下添加:
[mysqld] slow_query_log = ON slow_query_log_file = /data/mysql/logs/slow.log long_query_time = 1 log_queries_not_using_indexes = ONWindows环境下,配置文件通常位于MySQL安装目录下的my.ini,配置方式完全一致。
改完之后需要重启MySQL服务,或者用SET GLOBAL动态加载一遍(部分参数支持在线修改)。我的习惯是:先用SET GLOBAL在线打开,确认不影响业务后,再把配置写进my.cnf,避免重启造成不必要的连接中断。
2.3 阈值设置经验:千万别傻等10秒
long_query_time默认值是10秒,但说实话,10秒才抓一条慢SQL,对绝大多数业务来说太迟钝了。一个接口如果有2秒的数据库查询,用户体验已经很差了,但这个查询根本不会被记录。这就导致很多人开了慢查询日志,跑了一整天却什么都没抓到,然后得出“数据库没问题”的错误结论。
我个人的经验值:OLTP(在线事务处理)业务,阈值建议设置在1秒以内,先从1秒起步观察几天,如果日志量太大,再逐步调到2到3秒;如果日志量太小,就下调到500毫秒。对于复杂的报表系统、BI查询,可以放宽到5秒,因为这类查询本身执行时间长、频率低,没必要把阈值卡得太死。
另外,阈值修改后要注意:已经开启的慢查询日志不会因为阈值调低而马上补记,只有阈值调整之后新执行的SQL才会按新标准判断。这一点也容易产生误解。
3. 日志内容逐步拆解:看懂每一行都说了什么
3.1 慢查询日志文件的实际格式
日志打开后,很多人面对一堆# Time开头的文本不知道从哪看起。我摘一段典型的日志片段,逐行拆给你看:
# Time: 2025-06-21T10:24:36.872145Z # User@Host: root[root] @ localhost [127.0.0.1] Id: 8 # Query_time: 2.538375 Lock_time: 0.000174 Rows_sent: 1000 Rows_examined: 1250000 SET timestamp=1750487076; SELECT * FROM orders WHERE status = 1 ORDER BY create_time DESC LIMIT 1000;逐字段解读:
# Time:SQL执行的时间,注意这里默认是UTC时区。如果你发现记录的时间跟本地时间对不上,大概率是时区问题。可以检查time_zone参数,或者直接用date命令做换算。# User@Host:哪个账号、从哪个客户端IP发起的查询,便于定位是哪个应用服务器产生的问题。# Query_time:总执行时间,这是判断是否慢查询的核心指标,包含CPU执行时间和等待时间。# Lock_time:锁等待时间,包含行锁、表锁等待。如果这个值很大,说明SQL不是在“执行”上慢,而是在“等待别人释放锁”上慢,要往锁竞争方向排查。# Rows_sent:最终返回了多少行给客户端。# Rows_examined:扫描了多少行数据,这个值和Rows_sent的差距是判断索引效率的关键。SET timestamp=...:MySQL内部会在记录SQL前附带一条SET timestamp语句,它表示下面这条SQL执行时的Unix时间戳。- 剩下的就是原始SQL语句。
简单粗暴的判断标准:如果Rows_examined几十万、几百万,但Rows_sent只有几十、几百条,那基本可以认定这条SQL做了大量无用功,十有八九是索引缺失或者索引选择错误。
3.2 日志切割与历史归档
慢查询日志开启后,文件会持续增长。不管理的后果就是:磁盘被日志文件占满、数据库直接挂掉(尤其是日志放在系统盘上的情况)。我身边真实发生过数据库实例因为这个原因崩溃的案例,代价非常惨痛。
正确的处理方式是定期切割归档。MySQL本身没有自动切割慢日志的功能(不像binlog有max_binlog_size),需要我们手动操作。标准做法是利用mysqladmin flush-logs命令配合重命名:
# 先把当前日志改个名 mv /data/mysql/logs/slow.log /data/mysql/logs/slow_$(date +%Y%m%d).log # 生成新的空文件(重新打开日志句柄) mysqladmin -uroot -p flush-logs注意顺序不能反:必须先mv改名,再flush-logs。因为flush-logs会告诉MySQL“你现在写的是新文件”。如果你先flush再mv,那么mv操作会把MySQL正在写入的文件移走,导致一直在往旧文件里写,新的日志内容就丢失了。
把这个操作做成定时任务,每天晚上凌晨执行一次,日志保留30天,这样既方便问题回溯,又不会撑爆磁盘。脚本可以结合crontab来实现,就不在这里展开写完整脚本了。
4. 慢查询分析实战:工具与三类典型故障定位
4.1 内置工具 mysqldumpslow:日志太多看不过来怎么办
跑了一段时间后,慢日志里积累了几百条记录,人工逐条查看显然不现实。MySQL自带的mysqldumpslow工具能帮我们快速聚合日志内容,它会把结构相似的SQL归为一类,并统计出执行次数、总耗时、平均耗时等指标。
基本用法:
# 按执行次数从高到低排序,显示前20条 mysqldumpslow -s c -t 20 /data/mysql/logs/slow.log # 按总耗时排序,显示前10条 mysqldumpslow -s t -t 10 /data/mysql/logs/slow.log # 按平均耗时排序,显示前10条 mysqldumpslow -s at -t 10 /data/mysql/logs/slow.log # 输出原文,不把数字抽象成N、字符串抽象成S mysqldumpslow -a -s c -t 20 /data/mysql/logs/slow.log # 只看包含指定关键词的慢SQL mysqldumpslow -g "orders" /data/mysql/logs/slow.log参数说明:
| 参数 | 作用 |
|---|---|
-s c | 按执行次数排序 |
-s t | 按总执行时间排序 |
-s at | 按平均执行时间排序(默认是总时间,看平均更有价值) |
-s l | 按锁等待时间排序 |
-t N | 只显示前N条结果 |
-a | 不把数字和字符串抽象成N和S,显示原始SQL |
-g pattern | 过滤包含指定字符串的SQL |
默认情况下,mysqldumpslow会把SQL里的具体数字替换成N、字符串替换成S,这是为了把只差参数不同的同类SQL聚合到一起。比如WHERE id = 100和WHERE id = 200会被视作同一条SQL,统计在一起。如果只看原始SQL,带-a参数就行了。
这是官方自带工具的最大优势——零安装零依赖,只要有MySQL客户端环境就能用。对于更高阶的需求,可以考虑Percona Toolkit里的pt-query-digest,它能输出更详细的统计数据,甚至生成HTML报告,但这个工具需要单独安装,平时用mysqldumpslow其实已经能解决八成的问题了。
4.2 实战案例一:全表扫描导致的高Rows_examined
有一次排查线上商品订单接口变慢的问题,慢日志里频繁出现这样一条SQL:
# Query_time: 2.538375 Lock_time: 0.000174 Rows_sent: 1000 Rows_examined: 1250000 SELECT * FROM orders WHERE status = 1 ORDER BY create_time DESC LIMIT 1000;扫描了125万行,却只返回1000行,典型的全表扫描+临时文件排序。orders表当时只有id主键索引,status字段是普通列,没有任何索引。每次查询都要把整张表的记录全翻一遍,再按create_time排序取前1000条。
优化方案很简单,建一个复合索引:
ALTER TABLE orders ADD INDEX idx_status_create_time (status, create_time);这里有个细节:为什么建(status, create_time)而不是(status)或者(create_time)?因为这条SQL的查询逻辑是“按status过滤,再按create_time排序”,复合索引(status, create_time)正好能同时覆盖过滤和排序两个需求。MySQL在扫描索引时,定位到status=1的记录后,索引已经天然按create_time排好序了,可以省掉ORDER BY带来的文件排序(filesort)开销。
建完索引后,同一个慢查询的Rows_examined从125万降到了1052,Query_time从2.53秒降到了0.02秒,效果立竿见影。
4.3 实战案例二:隐式类型转换导致索引失效
接着上面订单表的问题,优化完两天后,慢日志里又出现了一批新SQL。这次的特点恰恰相反:Query_time不算太长,但频率极高。
# Query_time: 0.356200 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 350000 SELECT * FROM users WHERE phone = 13800138000;phone字段明明是varchar类型,但SQL里直接传了一个整数。MySQL在执行比较时,会把phone字段强制转换成数字类型再跟整数值比较。一旦对索引字段做了隐式转换,索引就失效了,MySQL只能放弃索引、走全表扫描。
这种问题最难排查,因为单条SQL执行只要300毫秒,根本不会引起注意,但QPS高的时候并发累积起来,数据库的连接数和CPU都会被打满。
解决办法有两个方向。第一个是把SQL改规范,写成字符串形式:
SELECT * FROM users WHERE phone = '13800138000';第二个是从代码层面根治,在业务代码里就保证参数类型与字段类型一致。我更推荐后者,因为只要应用层的传参逻辑不改,慢日志里还会反复出现类似SQL。
这类隐式转换问题,在排查时有个特征:EXPLAIN执行计划里possible_keys有索引,但key一列为NULL,或者干脆显示的rows扫描行数很大。记住这个规律,下次遇到可以少走很多弯路。
4.4 实战案例三:深分页limit带来的排序灾难
第三个案例很典型,几乎每个做业务系统的都会遇到。后台管理系统的订单列表,运维同事反馈翻到第5000页后,接口响应时间越来越长。慢日志中捕获到的问题SQL长这样:
# Query_time: 5.132550 Lock_time: 0.000045 Rows_sent: 20 Rows_examined: 2280020 SELECT * FROM orders WHERE status IN (1,2) ORDER BY id DESC LIMIT 300000, 20;问题根源在于LIMIT 300000, 20。MySQL执行这条SQL时,需要扫描前300020行,然后把前300000行全部丢弃,只留下最后20行返回。即使id主键索引存在也没用,因为索引并不能直接定位到第300000行的位置。
同时要注意,这里用了IN (1,2)条件,而解决方案里的索引idx_status_create_time在这种情况下也可能派不上用场。MySQL要先去status里面匹配两个值,然后把结果合并再排序,实际扫描行数依然非常惊人。
这类深分页问题有几种优化方案:
方案一:游标分页(推荐)
改造成“记住上一页最大id”的方式:
-- 首页 SELECT * FROM orders WHERE status IN (1,2) ORDER BY id DESC LIMIT 20; -- 翻页,传入上一页最后一条的id SELECT * FROM orders WHERE status IN (1,2) AND id < 上一页最小id ORDER BY id DESC LIMIT 20;这种方式的逻辑跟微信朋友圈下拉加载类似,往下翻页时只需要用id < 上次看到的最后一条来过滤,直接利用主键索引定位,扫描行数恒定在20行左右。
方案二:延迟关联(非连续翻页场景)
先利用覆盖索引查出目标id,再回原表取完整数据:
SELECT o.* FROM orders o INNER JOIN ( SELECT id FROM orders WHERE status IN (1,2) ORDER BY id DESC LIMIT 300000, 20 ) t ON o.id = t.id;子查询里id走主键索引,不需要回表扫描,性能比直接丢limit高几个数量级。
方案三:限制最大翻页深度
如果是后台管理系统,一个更务实的做法是限制翻页深度。用户不会真的去翻第10000页,系统最多允许查看前100页,超过就提示缩小查询范围。这个方案虽然“粗暴”,但直接把问题根治了,配合方案一使用效果最好。
5. 慢查询优化里的常见坑与我的排查心得
5.1 容易踩坑的几个点
有了前面这些案例基础,再来聊聊实践中最容易踩的坑。这些坑有些是经验问题,有些是认知问题,但都很容易被忽略。
第一个坑是只开日志不分析。我见过很多团队,慢查询日志开了好几个月,日志文件积累了十几个GB,却从来没人去翻过。开启慢查询日志只是工具,分析并推动优化才是目的。建议每周固定花一小时,用mysqldumpslow拉一份TOP10,把最频繁的几条SQL逐个做EXPLAIN,有条件的就优化,没条件的至少心里有数。
第二个坑是long_query_time没调过。很多人用默认的10秒,导致日志里一年都抓不到一条记录。建议从1秒起步,宁可记录多一点,也不要错过问题SQL。记录多了顶多费点磁盘,抓不到才是真的浪费这个功能。
第三个坑是日志文件放在系统盘。这属于一个比较危险的操作,慢日志增长过快时会把系统盘空间耗尽,导致数据库服务异常。我个人习惯于将慢日志、binlog等都放在数据盘单独规划的目录下,跟系统盘隔离。
第四个坑是上线配置改了但没重启加载。永久配置写进了my.cnf,但MySQL一直没重启,在线又没执行SET GLOBAL,导致实际上还是旧配置在运行。确认生效的方式是执行SHOW VARIABLES LIKE 'slow_query_log',看到ON才是真的开了。
第五个坑是生产环境错误地开启log_queries_not_using_indexes后全表扫描SQL刷屏。前面提到过,这个参数对开发环境的索引质量审查很有帮助,但在生产环境如果没有配套的告警和分析机制,日志会在几个小时内暴涨到几十GB。建议先用min_examined_row_limit设置一个扫描行数下限,比如10000,低于这个数量的SQL就不记录,这样能过滤掉大量无价值的记录。
5.2 完整的排查流程清单
根据我的实践,一个完整的慢查询排查流程可以按下面这个步骤走:
- 开启慢查询日志,阈值从1秒开始,确认日志文件写入正常。
- 运行一段时间(至少覆盖一个业务高峰),积累足够样本。
- 用
mysqldumpslow -s at -t 20拉取平均耗时前20的SQL。 - 挑出频率最高的几条,用
EXPLAIN查看执行计划。 - 依次检查:索引是否可用、是否被隐式转换干扰、是否需要复合索引、是否触发了文件排序、是否锁等待严重。
- 针对定位到的问题,设计优化方案:加索引、改SQL、改业务逻辑。
- 优化后持续观察慢日志,确认
Rows_examined和Query_time是否下降。 - 把成功案例沉淀下来,纳入团队SQL开发规范。
这个流程可以沉淀成团队的标准化动作。每一次优化都留下记录,后续新人排查问题的时候可以直接照着走,效率会高很多。我自己带的团队,基本就是靠这套流程来保证线上数据库的健康度。
5.3 个人经验与补充技巧
最后说几个我的个人经验,供你参考。
第一,慢日志只是起点,EXPLAIN才是终点。慢日志告诉你是哪条SQL慢,为什么慢要交给EXPLAIN去深挖。看执行计划的时候,重点关注type列(是否有ALL全表扫描)、key列(实际用了哪个索引)、rows列(预估扫描行数)、Extra列(是否出现Using filesort、Using temporary)。这四个字段能回答95%的问题。
第二,留意“快但频繁”的SQL。慢查询日志默认抓的是执行时间超过阈值的,但有很多SQL单次执行只有100毫秒,却在每秒钟被调用几百次。这类SQL带来的总开销可能比一条慢SQL还大。分析慢日志时,我会使用-s c按执行次数排序看一遍,而不是只看耗时最长的。
第三,锁等待问题要关联监控去看。如果一条SQL的Lock_time占Query_time的比例很高,说明问题不在SQL本身,而在锁竞争。这时候要看information_schema.innodb_trx和performance_schema里的锁等待信息,定位到阻塞源头是哪条事务没提交。单看慢日志容易把锅扣在SQL头上,实际是别的事务在搞事情。
第四,慢查询日志用久了,建议加一个“人工巡检+告警”机制。纯粹靠人肉看日志,总有疏忽的时候。现在很多数据库运维平台都支持对慢日志做监控告警,比如每分钟慢查询数量超过阈值就报警。即使没有平台,也可以写个简单的定时脚本,统计日志文件大小和新增条数,异常时发送通知。这样我们才能从被动救火变成主动防御。
另外有一个小技巧:如果遇到完全无法分析根源的“疑难杂症”,先把慢日志里的时间戳和业务访问日志对齐,看看那个时间点发生了什么大促活动、什么定时任务在跑,往往能定位到问题全貌。数据库的性能问题,从来都不只是数据库单方面的问题。