排查MySQL性能问题,我习惯做的第一件事就是翻慢查询日志。这个文件会按照我们设定的阈值,把所有执行时间超标的SQL原原本本记录下来,是定位数据库性能瓶颈最直接的入口。不管你是后端开发、运维还是DBA,只要跟MySQL打交道,慢查询日志都是你必须掌握的排查工具,因为绝大多数数据库性能问题,最终都会体现为一批“跑得慢”的SQL。这篇文章我就结合自己实际运维和调优的经验,把慢查询日志从配置、分析到优化、避坑完整地梳理一遍,争取让你看完就能直接用起来。
1. 慢查询日志是什么,为什么搞明白它很值
1.1 慢查询日志的核心概念
慢查询日志,也叫慢日志,是MySQL提供的一种日志记录能力,专门用来记录执行时间超过指定阈值的SQL语句。所谓“慢”,就是执行时间超过了我们设置的long_query_time参数,默认情况下这个值是10秒。注意,这里记录的是实际执行时间,不包含查询等待获取锁的时间,但日志里也会把锁等待时间单独列出来,这一点后面讲日志格式的时候会细说。
慢日志记录的不仅仅是SELECT查询,也包括UPDATE、DELETE、INSERT这类写语句。不过要注意一点,只有语句真正执行完成并且被判定为慢SQL时,才会写入慢日志。如果一条SQL执行到一半被kill掉,它是不会被记录到慢日志里的。这一点在实际排查线上问题时很容易踩坑,如果你发现某条SQL确实很慢但慢日志里没有,先想想是不是它根本没执行完就被中断了。
1.2 为什么慢查询日志是排查性能的第一站
我在处理公司线上数据库性能问题的时候,第一步几乎都是去看慢日志。原因很简单,慢日志直接告诉我们“哪些SQL慢、慢了多久、一天执行多少次”,这比拿着监控曲线猜要高效得多。MySQL的慢日志里记录了每条慢SQL的执行时间、锁等待时间、返回行数、扫描行数,甚至还有这条SQL是在哪个客户端、哪个用户下执行的。有了这些信息,我们就能快速把性能问题和具体的SQL对上号。
我见过很多团队,一发现数据库CPU飙高或者响应变慢,就急着加内存、加索引甚至扩容,其实很多情况下根源就是那么一两条写得很糟糕的SQL。如果没有慢日志做依据,很容易出现“机器加了一倍,问题依然在”的尴尬局面。慢日志就是那个帮你把“症状”和“病因”连接起来的关键证据。
1.3 和同类工具对比,慢日志好在哪里
MySQL能记录运行状态的途径其实不少。performance_schema里有一张events_statements_summary_by_digest表,也能找出消耗最高的SQL模板;开启general_log更是能把所有SQL不分轻重全记下来。但相比之下,慢日志的性价比是最高的:general_log记录量太大,生产环境开一天就能把磁盘写满,基本不适合长期开着;performance_schema虽然在MySQL 5.7以上已经很成熟,但对很多团队来说,配置复杂度偏高,而且默认采样也有一定限制。
慢日志的定位非常明确,只记录超出阈值的SQL,数据量可控,信息密度极高。配合mysqldumpslow或者Percona Toolkit里的pt-query-digest,几分钟就能从几万条慢SQL里找到真正需要优化的那几条。后面我会详细演示这两种分析工具的具体用法。
2. 开启慢查询日志的完整配置方案
2.1 动态开启方式,适合临时排查
如果你只是临时想排查一下当前实例的慢SQL,完全不需要重启MySQL,直接连上数据库执行几条SQL就行:
SET GLOBAL slow_query_log = 'ON'; SET GLOBAL long_query_time = 1; SET GLOBAL log_queries_not_using_indexes = 'ON';这里我把long_query_time设置为1秒,意思是只要SQL执行时间超过1秒就记录下来。生产环境我一般建议从1秒开始,先看看到底有没有慢SQL、量大不大,如果发现日志量实在太猛,再调整为2秒或者3秒;如果1秒的记录很少,可以再往下压到0.5秒,尽量把潜在问题暴露出来。
这里有一个必须知道的坑:long_query_time修改后,当前已经连接的会话依然使用旧值,只有新建立的连接才会使用新阈值。如果你执行完上面的命令后,用当前会话故意跑一条超过1秒的SQL,发现慢日志里没记录,不要以为是配置失效了,先重连数据库再测试。
动态开启方式在MySQL重启之后会失效,所以它适合临时排查场景。如果确认需要长期收集慢SQL,一定要走配置文件永久开启。
2.2 配置文件永久生效,一劳永逸
以Linux下最常见的my.cnf(也可能是my.ini,Windows环境)为例,在[mysqld]配置段下加入:
[mysqld] slow_query_log = 1 slow_query_log_file = /var/log/mysql/slow-query.log long_query_time = 1 log_queries_not_using_indexes = 1 log_throttle_queries_not_using_indexes = 10 min_examined_row_limit = 100配置项说明:
- slow_query_log = 1:开启慢查询日志,也可以写成ON。
- slow_query_log_file:指定慢日志文件的绝对路径。要确保MySQL的运行用户(通常是mysql用户)对该目录有写权限,否则日志写不进去,MySQL启动时还可能会报错。
- long_query_time = 1:慢查询阈值,单位秒,支持小数,比如0.5就表示500毫秒。
- log_queries_not_using_indexes = 1:记录所有没有走索引的SQL,即使执行时间没有超过阈值也会记录。这个选项是把双刃剑,有助于暴露隐性问题,但有些表数据量不大,全表扫描本身并不慢,开启后可能产生大量无效日志。建议先在测试环境观察一下日志量再决定开不开。
- log_throttle_queries_not_using_indexes = 10:上面的选项开启后,如果大量SQL都没用索引,日志会爆炸。这个参数限制每分钟最多记录10条未走索引的SQL,避免日志写爆磁盘。
- min_examined_row_limit = 100:只记录扫描行数至少100行的SQL。这个参数可以过滤掉那些扫描行数很少的查询,减小日志噪音。
修改完配置文件后,重启MySQL服务。不同系统的重启命令不太一样,systemd环境一般是systemctl restart mysqld,旧一点的SysV init环境是service mysql restart。重启前务必备份一下配置文件,别改错地方导致MySQL起不来。
2.3 我常用的几个参数组合
很多人只知道long_query_time,但实际性能排查中,这几个参数组合起来用效果更好。我自己的习惯配置是:
[mysqld] slow_query_log = 1 slow_query_log_file = /var/log/mysql/slow-query.log long_query_time = 1 log_queries_not_using_indexes = 1 log_throttle_queries_not_using_indexes = 5 min_examined_row_limit = 1000这里把min_examined_row_limit设置为1000,是因为我管理的业务表普遍数据量都不小,如果一条SQL只扫了几十行,即使没走索引,也说明表本身很小或者查询条件已经比较精准,不值得记录。设置成1000行以后,慢日志里留下来的基本都是“扫描量中等以上但速度不达标”的SQL,噪音明显降低。
如果你的业务是高频小查询类型,比如典型的C端接口,建议把long_query_time压到0.5秒甚至0.2秒,因为很多慢SQL在1秒以内就已经让接口响应变得不可接受了。先抓出来看,再根据实际情况决定要不要调整。
2.4 如何确认慢查询日志真的在记录
配置好之后,不要凭感觉认为“已经生效了”,我建议做一次完整的验证。先在MySQL里确认参数状态:
SHOW VARIABLES LIKE 'slow_query%'; SHOW VARIABLES LIKE 'long_query_time';正常的话,slow_query_log的值应该是ON,slow_query_log_file指向我们配置的路径。然后执行一条故意变慢的SQL,比如:
SELECT SLEEP(2);这条SQL会等待2秒,明显超过1秒的阈值。等它执行完之后,去查看日志文件:
tail -20 /var/log/mysql/slow-query.log如果能看到包含SELECT SLEEP(2)的日志段,说明整个链路已经通了。这里我要特别提醒一个细节:慢日志是语句执行完成之后才写入的,所以执行完SLEEP(2)后要稍微等一两秒再看日志,别急着立刻tail。验证完毕之后,记得在代码里不要留着这种测试用的慢SQL。
3. 慢查询日志的分析方法与核心实操
3.1 日志格式逐字段拆解
慢日志虽然是文本文件,但它的格式是结构化的。我截取一条真实风格的日志来逐字段拆解:
# Time: 2024-06-12T10:24:35.882817Z # User@Host: app_user[app_user] @ [10.20.3.15] Id: 482157 # Query_time: 3.251234 Lock_time: 0.000217 Rows_sent: 10 Rows_examined: 1023456 SET timestamp=1718173475; SELECT id, order_no, amount FROM orders WHERE user_id = 12345 ORDER BY create_time DESC LIMIT 10;先看Time这一行,这个时间戳记录了SQL执行完成的时刻,注意这是UTC时间,如果你要跟业务日志对齐排查,记得换算成东八区时间,通常要加8小时。User@Host表示这条慢SQL是由哪个用户从哪个客户端IP发起执行的,对于定位“哪个应用节点打过来的慢请求”很有用。
Query_time是核心指标,指SQL实际执行耗时,单位秒。Lock_time是锁等待时间,如果这个值比较大,通常意味着不是SQL本身的执行计划慢,而是它一直在等待别的会话释放锁。判断的时候有个小技巧:如果Query_time很大但Lock_time很小,问题多半出在SQL执行计划上;如果Lock_time占了Query_time的大部分,要优先排查锁竞争。Rows_sent是最终返回给客户端的行数,Rows_examined是这条SQL在存储引擎层扫描了多少行。这两者的比值非常关键,如果扫描了上百万行只返回10行,那就说明定位数据的方式出了问题,很可能索引没建对。
接下来那一行SET timestamp=...是这条SQL开始执行的时间戳(Unix时间),后面跟的就是完整SQL原文。注意日志里记录的SQL一般不会带参数展开,如果应用使用了PreparedStatement,这里记录的是带问号的模板SQL,这对于按模式归并统计来说反而是好事。
3.2 用mysqldumpslow快速定位Top SQL
mysqldumpslow是MySQL自带的分析工具,不用额外安装。它会把结构相同只是参数不同的SQL自动归并成一条模板,然后按各种维度排序,这对快速摸清慢日志的整体情况非常友好。常用的命令有这几个:
# 按平均执行时间排序,看最慢的前10条 mysqldumpslow -s t -t 10 /var/log/mysql/slow-query.log # 按执行次数排序,看最频繁的前10条 mysqldumpslow -s c -t 10 /var/log/mysql/slow-query.log # 按总执行时间排序,适合找出拖累数据库总耗时的头号嫌疑 mysqldumpslow -s at -t 10 /var/log/mysql/slow-query.log参数说明:-s t表示按平均执行时间排序,-s c表示按出现次数排序,-s at表示按总执行时间排序;-t 10表示只显示前10条。输出结果里会看到类似这样的内容:
Count: 320 Time=2.81s (900s) Lock=0.00s (0s) Rows=500.0 (160000), app_user[app_user]@[10.20.3.15] SELECT * FROM orders WHERE user_id = N ORDER BY create_time DESC LIMIT NCount表示这种模式的SQL在日志中出现过320次,Time=2.81s是平均执行时间,括号里的900s是总执行时间。看到这种结果基本就能确定:这条SQL平均2.8秒,一天命中320次,总耗时900秒,属于必须优先处理的头号对象。
mysqldumpslow的缺陷是不支持把结果显示成更丰富的报表,而且它对SQL模板的归并相对粗犷,如果要深入了解某个SQL模板的耗时分布、索引命中情况,就得用下面这个更强的工具。
3.3 用pt-query-digest做深度分析
pt-query-digest是Percona Toolkit里的明星工具,没有自带安装,需要单独装。它读取慢日志后,会生成一份非常完整的报告,按总执行时间排序把慢SQL分门别类,每个类下面还有响应时间占比、执行次数、平均耗时、百分位耗时、扫描行数等统计信息。安装方法在CentOS上一般是这样:
yum install percona-toolkit然后用它分析慢日志:
pt-query-digest /var/log/mysql/slow-query.log > slow_report.txt打开slow_report.txt,重点看每个SQL模板的“Response time”这一项,它显示了该SQL累计耗时占全部慢SQL总耗时的百分比。我拿到报告后一般直接从占比最高的那个开始看,因为优化它收益最大。比如报告里显示某条SQL占整体慢查询耗时的45%,那把它优化掉,数据库的慢查询压力几乎减半。
pt-query-digest还可以直接连上MySQL,从information_schema等表里实时分析当前正在执行的查询,但我用得最多还是离线分析日志的方式。如果日志文件特别大,比如超过1GB,建议先用pt-query-digest的--limit或者--filter参数做一下筛选,别让分析过程把服务器CPU吃满。
3.4 手工分析SQL模板的常见技巧
有些场景下,公司服务器安全策略比较严格,不让安装额外工具,那只能靠手工从慢日志里抓信息。我自己的做法是分段处理。先用grep把包含Query_time的行捞出来,按执行时间排序,看看有没有特别离谱的慢查询,比如超过10秒甚至几十秒的:
grep "Query_time:" /var/log/mysql/slow-query.log | awk '{print $3}' | sort -rn | head -20然后直接根据时间区间头尾截取对应的日志段,结合业务高峰期去分析。比如业务方报告每天上午10点接口变慢,而慢日志里10:00到10:30正好集中出现某几条SQL模板,那基本上就可以确定问题范围了。手工分析虽然效率低,但配合SELECT SLEEP这种手段做小范围验证,在小型团队里也完全够用。
手工分析还有一个技巧:针对同一条SQL模板,把日志里多次出现的Rows_examined拉出来对比。如果这些扫描行数相差不大,说明执行计划比较稳定,问题主要出在数据量本身;如果同样一条SQL,扫描行数忽高忽低,那就要考虑是不是没有走同一个索引,或者数据分布发生了倾斜。结合EXPLAIN去看,往往能很快找到真相。
4. 慢查询背后的原因诊断与优化策略
4.1 用EXPLAIN看懂执行计划
慢SQL抓出来只是第一步,真正要解决它,必须搞清楚为什么慢。最直接的手段就是EXPLAIN。举个简单例子:
EXPLAIN SELECT id, order_no, amount FROM orders WHERE user_id = 12345 ORDER BY create_time DESC LIMIT 10;重点看几个字段。type字段是访问类型,它的取值从坏到好大致是ALL、index、range、ref、eq_ref、const。最怕的是ALL,说明这条SQL在做全表扫描。key是实际使用的索引,如果显示NULL,说明这次查询没有可用的索引。rows是预估扫描行数,这个数字越小越好。Extra字段里如果出现Using filesort,说明排序没法用索引完成,需要在内存或者磁盘上做额外排序,这也是导致慢查询的常见原因。
EXPLAIN给出的rows只是估算值,但相对趋势是可信的。前后对比时,只要rows从百万级降到几千,执行速度几乎必然有质的提升。日常排查时我还会用到EXPLAIN EXTENDED的增强版信息,但基础这几个字段已经能覆盖绝大多数场景了。
4.2 索引相关的最常见慢SQL
慢查询里最典型的一类就是索引问题。我归纳成三种情况。
第一种是压根没建索引。很多业务表前期数据量小,开发图方便,对where条件没建索引,等数据量上了千万级之后,一条简单的等值查询都可能跑好几秒。比如上面的orders表,如果user_id没有索引,按用户查订单就是全表扫描。这种情况直接加一个普通索引就能解决。
第二种是索引建了但失效。最常见的原因是隐式类型转换。假如user_id字段是varchar类型,但应用传进来的参数是数字,或者SQL里写成了user_id = 12345,MySQL可能无法直接利用索引做等值匹配。另一个高发场景是在索引列上套函数,比如WHERE DATE(create_time) = '2024-06-12',这种写法导致create_time上的索引完全失效。解决办法是改写为范围查询:WHERE create_time >= '2024-06-12 00:00:00' AND create_time < '2024-06-13 00:00:00'。
第三种是复合索引设计不合理。最常见的是不遵守最左前缀原则。比如建了索引idx_user_create(user_id, create_time),SQL里却直接用create_time排序,这个索引就排不上用场。反过来,如果你发现某条慢SQL经常同时按user_id过滤又按create_time排序,那就应该检查现有索引是否覆盖了这两个条件,而不是简单粗暴再加一个单列索引。
4.3 锁等待与事务造成的慢查询
慢日志里的Lock_time如果异常偏高,说明这条SQL大部分时间都卡在等待锁释放上,这时候加索引往往没什么用,要解决的是锁争用问题。InnoDB的行锁、间隙锁、表锁以及MDL元数据锁,都可能导致SQL慢得离谱。
最常见的场景有两个。第一个是大事务迟迟不提交。应用里开启了事务,执行了事务内的多条写操作,却长时间不提交,导致其他会话的写操作和某些读操作被行锁阻塞。排查方式是在processlist里看有没有长事务,或者查看information_schema.innodb_trx表。
第二个是热点行更新。比如秒杀场景下,同一个商品ID的库存字段被大量并发更新,行锁竞争自然非常激烈。这种问题靠SQL层面很难根治,要在业务设计上做拆分,比如把库存拆成多个子库存记录,或者引入异步队列。慢日志的作用是帮你确认“到底是不是锁导致的”,避免白做索引优化。
还有一类容易被忽略的是DDL操作引起的MDL锁阻塞。如果业务高峰期间执行了ALTER TABLE,哪怕只改一个字段,也可能导致大量相关SQL被阻塞。我自己就遇到过线上执行ALTER TABLE加索引,结果造成了一大片select被阻塞的情况。解决办法是把大表DDL安排在低峰期,或者用在线DDL工具做平滑变更。
4.4 一个完整的优化流程示例
我拿一个实际优化过的例子走一遍完整流程。当时有个订单报表接口,每天定时跑,调用方反馈越来越慢,后来直接影响了业务方出报表的时效。我先翻慢日志,定位到一条典型SQL:
SELECT * FROM orders WHERE user_id = 10086 AND create_time BETWEEN '2024-05-01' AND '2024-05-31' ORDER BY create_time DESC;先用EXPLAIN看执行计划,发现type是ALL,rows估算超过200万,Extra里有Using filesort。这说明orders表根本没有支持user_id+create_time的复合索引。当时表里只有一个主键索引和一个user_id单列索引。
于是我先做一个最小改动,加复合索引:
ALTER TABLE orders ADD INDEX idx_user_create (user_id, create_time);加完索引后,EXPLAIN显示type变成了range,rows降到了数千,Extra里的Using filesort也消失了。从慢日志看,这条SQL的执行时间从原来的平均3.2秒降到了0.15秒,效果立竿见影。
但事情还没结束。我再看同一条SQL模板,发现Rows_examined虽然降了,但部分大用户的订单量还是很大,分页拉到后面几页依然慢。这是因为LIMIT深分页的固有缺陷:MySQL需要扫描并丢弃大量满足条件的行才能返回目标数据。我改用了延迟关联写法,先只查主键再回表:
SELECT o.* FROM orders o INNER JOIN ( SELECT id FROM orders WHERE user_id = 10086 AND create_time BETWEEN '2024-05-01' AND '2024-05-31' ORDER BY create_time DESC LIMIT 1000, 20 ) t ON o.id = t.id;这个改动之后,即使翻到很深的页数,性能也保持稳定。整个优化过程,从慢日志定位、EXPLAIN分析、加索引到改写SQL,每一步都有据可依,这就是标准化的排查路径。
5. 常见问题与排查技巧实录
5.1 常见问题速查表
我在维护慢查询日志的过程中,积累了一些高频问题的排查经验,整理成一张速查表供参考。
| 问题现象 | 可能原因 | 排查方法 | 解决办法 |
|---|---|---|---|
| 慢日志没有产生任何内容 | 阈值设置过大,或语句没执行完成 | 检查long_query_time,用SLEEP(2)主动测试 | 调低阈值,确认参数已生效 |
| 日志文件越来越大,磁盘告警 | long_query_time过小,或未走索引SQL过多 | 查看日志大小与条数 | 调高阈值,开启log_throttle限制,配置日志轮转 |
| 修改GLOBAL参数后不生效 | 会话级变量未更新 | 新开连接再测试 | 重新连接MySQL后验证 |
| 慢日志里没有某条已知慢SQL | 语句执行被中断,或连接用的账号无权限记录 | 检查是否完成执行 | 区分正常超时与KILL场景 |
| MySQL重启后配置丢失 | 只用了SET GLOBAL动态开启 | 查看配置文件是否包含参数 | 写入my.cnf并重启 |
| 日志写不进去,启动报权限错误 | 日志目录属主不是mysql用户 | 检查slow_query_log_file路径权限 | chown mysql:mysql 目录 |
5.2 我踩过的几个坑
第一个坑是长期开着log_queries_not_using_indexes导致日志爆炸。有一次我在某台业务实例上开了这个参数,没设置log_throttle,结果一个小时后磁盘可用空间从40%直接掉到5%,最后只能紧急清理日志文件。从那以后我在生产环境开这个参数时一定同时开log_throttle,而且先在低峰期试运行一段时间观察日志增量。
第二个坑是配置了slow_query_log_file到自定义目录,但没有确认MySQL的selinux策略。在开启了SELinux的系统上,MySQL默认只允许写某些特定目录,即使目录权限设成了777,写入还是会被拒绝。我当时排查了很久才发现问题,后来直接用系统自带的/var/log/mysql目录,或者执行chcon调整上下文,这个细节在安全加固过的服务器上很容易踩。
第三个坑是清理慢日志文件的方式不对。有些人习惯直接rm掉慢日志文件,但MySQL进程还持有那个已经删除的文件的句柄,磁盘空间并没有释放,而且后续日志继续写入到一个看不到的“幽灵文件”里。正确做法是先用mv把日志文件改名,然后执行mysqladmin flush-logs让MySQL重新生成一个新文件,再删除旧文件。
5.3 慢查询日志之外的建议
慢查询日志是发现慢SQL的入口,但不是唯一手段。我通常还会配合performance_schema里的events_statements_summary_by_digest表,直接按SQL模板统计总执行次数和总耗时,用来验证慢日志里发现的问题是否与整体负载一致。如果慢日志里某条SQL总耗时排第一,但它在全量SQL统计里占比不高,说明它只是偶发变慢;如果两边都显示它是大头,那这个问题就是稳定持续存在的,优先级要提到最高。
另外,慢日志一定要配置好自动轮转。Linux自带的logrotate配合MySQL的flush-logs是常见方案。我一般每周做一次轮转,保留最近8周的文件,这样既避免磁盘被打满,又能给故障排查保留足够的历史数据。归档后的慢日志文件名建议加上日期后缀,方便后续回溯。
写在最后
从我个人经验看,慢查询日志最大的价值不是“记录”,而是“指引”:它指引你把宝贵的优化时间花在真正值得优化的SQL上。每次拿到一份慢日志,先看占比最高的SQL模板,再分析执行计划,有针对性地加索引或者改写SQL,这样一轮下来,数据库的整体响应能力通常都能获得明显提升。上面分享的配置参数、分析工具和排查思路,都是我一步步踩坑之后总结出来的,你可以根据自己的业务特点调整阈值和策略。相信把这套方法用熟了,再遇到数据库性能问题,你心里就有底多了。