在接手别人留下的MySQL实例时我第一件事往往不是看表结构、看索引而是先翻慢查询日志。原因很简单慢日志是一个数据库实例在性能问题上最诚实的第一现场——应用层可以撒谎、监控系统可能漏报但一条真实的慢SQL记录就摆在那里执行了多久、锁了多长时间、扫描了多少行所有关键证据都在里面。这篇文章我想系统梳理一下慢查询慢日志从配置、采集到分析、优化的完整链路。不是单纯讲参数怎么设而是把我实际排查性能问题时的那套思路也一并带出来——为什么这么配、日志该怎么读、拿到一条慢SQL之后先看什么再看什么这些才是真正能帮你在生产环境里少走弯路的经验。1. 慢日志是什么以及它到底能帮你抓住什么问题1.1 慢日志记录的并不是“所有慢操作”很多刚接触MySQL的人会有一个误解以为慢查询日志会像监控系统一样把执行超过某个阈值比如1秒的SQL全部记录下来。实际上它的工作方式要更“原生”一些——MySQL在语句执行结束后会判断这条语句的实际执行耗时是否超过了预设的阈值如果超过就把这条语句连同执行时间、锁等待时间、扫描行数等元信息一起写入日志文件。这里有个非常关键、也经常被忽略的细节慢日志的判定时机是语句执行完成之后而不是执行开始之前。这就意味着一条SQL如果执行到一半被客户端取消比如应用超时主动断开MySQL可能不会把它记入慢日志因为语句没有正常结束执行统计信息不完整。一条SQL如果因为等待元数据锁MDL被阻塞了很久那么“等待锁的时间”会被单独拆出来记录而真正的执行时间未必长。这类SQL往往是“看起来慢、实际上是别人堵着它”的典型案例。所以慢日志的本质是一份“结果导向”的体检报告它告诉你哪些语句最终花了很长时间才跑完但它不会主动告诉你“为什么”慢。为什么慢需要你结合执行计划、表结构、索引情况去进一步分析——这正是后面几节要展开的内容。1.2 慢日志能发现、但不容易发现的几类问题在实际生产环境里慢日志的价值主要体现在三个方面定位“查询慢”的源头。这是最基本的作用。某个接口突然从50毫秒涨到2秒慢日志里大概率能看到对应的SQL结合时间戳还能反推是不是某次发版、某个新功能上线导致的。发现“会越来越慢”的隐患。有些SQL今天跑200毫秒但数据量翻倍后可能就变成2秒。慢日志能帮你提前把这些“潜在炸弹”找出来在数据量还没涨到临界点之前优化掉。侧面印证“锁等待”问题。如果慢日志里大量出现执行时间很短、但锁等待时间很长的语句说明系统里存在锁竞争这时候重点不是优化SQL本身而是优化并发逻辑和事务隔离级别使用方式。但也要坦白说慢日志对“偶发性慢查询”的捕捉能力是有限的。比如一个线上实例每秒有几百条查询只有极少数几条因为某种瞬时原因比如buffer pool被LRU刷出、磁盘IO抖动慢了一次如果阈值设得比较高这些偶发慢查询可能根本不会被记录。想要抓这类问题单靠慢日志是不够的还得配合performance_schema或第三方监控工具的语句级采样。慢日志更适合抓“稳定慢”和“持续慢”的问题。2. 慢日志的开启、配置与底层写入机制2.1 核心参数与推荐配置开启和配置慢日志涉及几个核心参数。默认情况下MySQL的慢日志是关闭的如果你发现自己实例的slow_query_log变量值为OFF那就意味着过去所有慢查询你都没有留痕——这是件挺可惜的事毕竟磁盘空间换性能排查线索这笔账怎么算都划算。直接给出一套我个人在线上环境常用的配置作为参考参数名推荐值说明slow_query_logON开启慢查询日志slow_query_log_file/data/mysql/log/slow.log日志存放路径建议放在独立磁盘分区long_query_time1或0.5阈值单位秒生产环境建议从1秒开始精细化再调低log_queries_not_using_indexesON记录所有没有走索引的SQL即使执行很快log_throttle_queries_not_using_indexes10每秒最多记录10条未走索引的SQL防止刷爆日志min_examined_row_limit100只记录扫描行数超过100行的语句过滤掉无意义的短查询log_slow_admin_statementsON记录ALTER TABLE等管理语句的慢执行log_outputFILE输出到文件便于集中采集分析这里想特别说一下long_query_time这个值怎么定。我见过不少团队把它设成10秒理由是“我们系统没那么慢的SQL”。但等你真的遇到问题时就会发现10秒的阈值会让所有“从1秒恶化到9秒”的SQL完全逃过监控等到它们突破10秒被记录时业务可能已经受到影响了。更合理的做法是先设一个比较敏感的阈值比如0.5秒跑一两周把所有超过这个阈值的SQL都捞出来逐个分析哪些值得优化、哪些是正常的“重查询”。等把该处理的都处理完之后再把阈值调回1秒甚至更高一些作为长期监控线。敏感期抓全稳定期抓准这才是阈值配置的正确节奏。2.2 慢日志的底层写入细节慢日志的写入机制比较简单粗暴MySQL会在语句执行结束后把超过阈值的语句格式化成固定结构的文本行追加写入日志文件。但这里有几个容易被忽略的细节第一日志刷盘策略。与binlog不同慢日志本身不涉及事务一致性问题所以它的写入策略相对简单由log_output变量决定。输出到文件时MySQL先写入操作系统的文件系统缓存刷新到磁盘的时机依赖于操作系统自身的刷盘策略。这意味着如果实例突然宕机最近一小段时间的慢日志可能会丢失——但对于排查慢查询来说丢失几条日志往往影响不大因为慢查询是持续性的问题不是每秒都有价值的东西。第二针对未使用索引的SQL记录有点特殊。当log_queries_not_using_indexes开启后MySQL会额外记录那些虽然执行很快但没走索引的SQL。这类SQL真正的危险在于数据量增长之后“突然变慢”所以提前把它们记下来做预防性优化非常有价值。但要注意这个选项在低负载实例上可能产生大量日志所以务必配合log_throttle_queries_not_using_indexes做限流。第三关于管理语句。默认情况下ALTER TABLE这类管理语句的慢执行是不记录到慢日志的从MySQL 5.1.6之后的行为所以如果你遇到“某个大表DDL是不是卡住了”这类问题会发现慢日志里根本没有线索这个坑我已经踩过。开启log_slow_admin_statements之后这类语句的耗时才能被记录下来。2.3 在线开关不影响业务但不能随便改文件慢日志的开启和关闭是动态参数直接在MySQL命令行执行SET GLOBAL slow_query_log ON;就能生效不需要重启实例也不需要终止当前连接。这一点在生产环境里非常友好意味着你可以在发现性能问题时立刻开始采集不需要等待变更窗口。但有一个操作要特别提醒不要在实例运行期间手动去移动或删除慢日志文件。有同学觉得日志文件太大直接mv走或者rm掉结果MySQL的句柄还指向原文件磁盘空间没释放新日志也继续往那个已删除的inode上写。正确做法是# 正确清理方式先关闭慢日志再处理文件再重新开启 mysql SET GLOBAL slow_query_log OFF; # 然后正常mv或者压缩日志文件 mv /data/mysql/log/slow.log /data/mysql/log/slow_$(date %F).log # 重新开启 mysql SET GLOBAL slow_query_log ON;或者使用MySQL 5.6.6支持的mysqld_safe自动重开机制但手动走这个三段式流程更稳妥可控。3. 慢日志里每行字段的含义以及怎么从日志反推问题现场3.1 一段典型的慢日志长什么样开启慢日志并触发一条慢查询之后日志文件里会有这样一段记录# Time: 2024-11-18T10:23:45.123456Z # UserHost: app_user[app_user] [192.168.1.88] Id: 23456 # Query_time: 2.345678 Lock_time: 0.001234 Rows_sent: 10 Rows_examined: 587321 SET timestamp1731911025; SELECT o.order_no, u.user_name, p.pay_amount FROM orders o JOIN users u ON o.user_id u.id JOIN payments p ON o.order_id p.order_id WHERE o.created_at BETWEEN 2024-11-01 00:00:00 AND 2024-11-18 23:59:59 AND o.status PAID ORDER BY o.created_at DESC LIMIT 10;这短短五行文本信息量其实非常大。第一行是语句开始执行的时间注意这里是# Time表示的是语句执行的起始时间不是写日志的时间第二行是用户、来源IP、连接ID第三行是核心指标——总耗时、锁等待耗时、返回行数、扫描行数第四行的SET timestamp...非常关键它记录了这条语句在数据库内部执行时的时间戳方便你在做数据回溯时与业务日志、应用日志对齐第五行开始才是完整的SQL文本。3.2 最该先看的三组关系从排查经验来说拿到一条慢日志记录不要急着看SQL长什么样先看三组关系第一组Rows_examinedvsRows_sent。这一组对比能直接告诉你SQL的“效率”。示例里扫描了58万行只返回10行扫描返回比接近6万比1说明绝大部分扫描工作都白做了。这类SQL八成出在JOIN连接顺序不对、索引缺失或WHERE条件写得不满足索引使用条件上。正常优化后的目标是让Rows_examined尽可能接近Rows_sent理想状态是1:1左右。第二组Query_timevsLock_time。如果Lock_time占了Query_time的一半以上说明瓶颈不在SQL本身执行而在等待其他事务释放锁。这时候你去看SQL本身、去加索引效果都不好重点应该转向查看performance_schema.data_lock_waits或information_schema.INNODB_TRX找出是谁长时间占着锁不释放。第三组连接ID和来源IP。通过Id: 23456可以反查performance_schema.threads或information_schema.processlist在当时的连接状态配合来源IP通常能定位到具体是哪个应用服务、哪个业务模块发起的慢查询。如果同一来源IP频繁出现说明某个服务的SQL写法有问题可以考虑推动应用侧整改。3.3 日志时间戳和业务日志对齐的技巧SET timestamp1731911025这行很多人会忽略但它在跨系统排查时极其有用。比如业务方反馈“下午3点那会儿某个页面特别卡”你翻慢日志看到# Time: 2024-11-18T10:23:45Z——注意这里默认是UTC时间。如果你直接拿这个时间去对业务日志会发现怎么都对不上差了好几个小时。这是因为MySQL的慢日志时间默认使用UTC时区记录除非你在启动时配置了log_timestamps参数。正确做法是# 查看当前日志时间戳设置 SHOW VARIABLES LIKE log_timestamps; # 如果返回SYSTEM则日志使用系统时区如果返回UTC就需要换算如果你的业务团队习惯用东八区时间排查问题建议显式设置log_timestamps SYSTEM并确保操作系统时区是东八区这样慢日志里的# Time直接就是北京时间和业务日志天然对齐。这个参数不需要重启可以动态修改。4. 从“看日志”到“定位根因”聚合统计与执行计划分析4.1 先聚合再细看两类分析工具的使用差异慢日志单条单条看是没有意义的尤其是持续慢的实例日志里可能躺着成千上万条记录。正确的方法是先做聚合统计找到“哪几类SQL贡献了最多的慢查询”再聚焦这几类做细致分析。系统自带的mysqldumpslow工具是最轻量的选择适合快速看一眼整体分布# 统计访问次数最多的20条慢SQL mysqldumpslow -s c -t 20 /data/mysql/log/slow.log # 统计平均查询时间最长的10条慢SQL mysqldumpslow -s at -t 10 /data/mysql/log/slow.log # 把结果输出到文件方便二次处理 mysqldumpslow -s t -t 50 /data/mysql/log/slow.log /tmp/slow_top50.txtmysqldumpslow会自动把SQL中的具体值抽象成N和S比如WHERE id N这样统计时能把同一类SQL聚合到一起。这一点非常实用——生产环境里每条SQL的参数值都不同如果直接按全文匹配去重会出现“同一条SQL因为参数不同被当成成千上万条不同SQL”的假象。**第三方工具pt-query-digest**则是更强大的选择。它能输出一份结构化的报表除了基础的TOP SQL耗时排名还会对每条SQL给出“总耗时占比”“平均行数”“百分位耗时95%、99%”等更细的指标并且会识别出SQL指纹把字面量替换成占位符之后生成的哈希值聚合维度更精准pt-query-digest /data/mysql/log/slow.log /tmp/slow_analysis.html对于日常巡检来说我会先用mysqldumpslow -s c看个大概再用pt-query-digest深入看具体SQL的执行特征。如果实例上没有安装Percona Toolkitmysqldumpslow也完全够用不要为了追求工具而复杂化流程。4.2 锁定一条慢SQL后EXPLAIN才是核心武器假设聚合之后你锁定了下面这条SQL是慢查询的元凶SELECT u.id, u.nickname, COUNT(o.id) AS order_count FROM users u LEFT JOIN orders o ON o.user_id u.id WHERE u.reg_time 2024-01-01 GROUP BY u.id ORDER BY order_count DESC LIMIT 20;接下来要做的不是凭感觉“加个索引试试”而是用EXPLAIN看它的执行计划EXPLAIN SELECT u.id, u.nickname, COUNT(o.id) AS order_count FROM users u LEFT JOIN orders o ON o.user_id u.id WHERE u.reg_time 2024-01-01 GROUP BY u.id ORDER BY order_count DESC LIMIT 20\G输出结果大致如下*************************** 1. row *************************** id: 1 select_type: SIMPLE table: u type: ALL possible_keys: PRIMARY, idx_reg_time key: NULL key_len: NULL ref: NULL rows: 521834 filtered: 10.25 Extra: Using where; Using temporary; Using filesort *************************** 2. row *************************** id: 1 select_type: SIMPLE table: o type: ref possible_keys: idx_user_id key: idx_user_id key_len: 8 ref: db1.u.id rows: 23 filtered: 100.00 Extra: NULL这份执行计划里信息量很大我一条条拆开解读type: ALL在users表上走了全表扫描这是最差的情况之一意味着MySQL要从头到尾读完整张用户表。估算扫描行数52万这是在数据量增长后逐渐恶化的典型表现。key: NULL尽管possible_keys里有idx_reg_time索引但优化器最终没有使用它。原因和WHERE u.reg_time 2024-01-01这个条件有关——如果满足条件的行数占比太高优化器会认为“走索引再回表的成本比直接扫全表更高”这是优化器的正常判断但在这个SQL里它恰恰忽略了一个矛盾少了一个索引之后后续的GROUP BY计算需要把所有扫描行都放进临时表反而更慢。Using temporary; Using filesort是这里真正的瓶颈。GROUP BY u.id和ORDER BY order_count DESC的组合导致MySQL需要把中间结果先写入临时表temporary table再在临时表上做一次排序filesort。临时表和文件排序都是内存/磁盘资源消耗大户大量并发执行时还会加剧buffer pool的竞争。4.3 一个典型的优化推演从执行计划出发基于上面的分析优化思路就很清晰了。可以先尝试让users表上的过滤走索引减少参与JOIN和GROUP BY的行数——但前面说过过滤条件reg_time 2024-01-01如果覆盖太多行优化器未必买账。更有效的方案是调整JOIN顺序和索引设计给orders表建立(user_id, id)的联合索引让COUNT(o.id)可以从覆盖索引直接统计避免回表读取完整行数据。在users表上把GROUP BY u.id的主键特性用起来因为u.id本身是主键建一个(reg_time, id)的联合索引让过滤和分组都走索引。如果业务允许把ORDER BY order_count DESC放到应用层排序数据库只负责输出未排序的聚合结果减少一次filesort。改完后再次EXPLAIN验证type从ALL变成rangeExtra里的Using temporary; Using filesort消失执行时间从秒级降到几十毫秒级。整个过程要时刻记住先看执行计划找问题再针对问题设计索引或改写SQL最后用优化后的执行计划验证效果这是无论如何都不能跳过的三步。5. 真正的隐患往往不是“慢”而是“还没慢但会慢”5.1 全表扫描的SQL为什么值得警惕很多人对慢日志的理解有一个误区只要Query_time没超过阈值就认为SQL没问题。但如果你开启了log_queries_not_using_indexes参数就会发现大量“执行了30毫秒、但扫描了200万行”的SQL躺在日志里。这类SQL现在不慢是因为机器性能好、数据页都在内存里可在以下两种情况下它们会瞬间变成灾难数据量继续增长。200万行变成2000万行执行时间大概率不是线性增长而是指数级恶化。原来30毫秒的查询等扫描行数涨10倍后可能直接变成2秒甚至更久。冷数据场景。如果实例buffer pool不够大这些全表扫描会把热数据页全部挤出内存导致其他正常查询也被拖慢。这类问题往往表现为“整个实例突然变慢但看每一条SQL都不算太慢”。所以我在巡检时对Rows_examined的关注程度甚至高于Query_time。一条读取了上百万行数据的SQL无论当前执行多快都要纳入优化计划哪怕它现在的耗时只有100毫秒。5.2 参数化造成的“同一条SQL”假象在聚合慢日志时还要注意一个细节mysqldumpslow会做参数化归类pt-query-digest会生成SQL指纹这是好事——能帮我们把同一语义的SQL聚到一起。但正因为它们做了“归一化”有一些真正需要区分的信息会丢失。比如下面两条SQL-- 第一条 SELECT * FROM orders WHERE user_id 1001 ORDER BY created_at DESC LIMIT 20; -- 第二条 SELECT * FROM orders WHERE user_id 99999999 ORDER BY created_at DESC LIMIT 20;在聚合工具眼里它们会被归为同一个指纹。但实际执行计划可能完全不同user_id 1001的用户订单有几万条排序消耗大user_id 99999999的用户可能一条订单都没有它慢的原因可能是“索引选择错误”或者“统计信息过期”。如果只看聚合结果你会以为这条SQL很稳定实际上它内部的行为一直在波动。解决方法是聚合之后一定要挑几条典型SQL拿到原日志里看原文和真实参数值再结合业务情况判断是否存在“数据倾斜”或“统计信息失准”的问题。聚合看全局单条看细节两者缺一不可。5.3 统计信息过期为什么会让索引策略失灵MySQL优化器决定是否使用索引主要依赖表的统计信息cardinality、行数等。当表数据发生大量增删改之后如果统计信息没有及时更新优化器可能基于过期数据做出错误判断——明明有索引可用但优化器觉得“走全表扫描更划算”结果就是慢查询突然增多。处理方式有几种-- 方式一手动更新统计信息 ANALYZE TABLE orders; -- 方式二查看表的行数估算是否偏离实际 SHOW TABLE STATUS LIKE orders;生产环境里我遇到过不止一次“慢日志里某条SQL从昨天开始突然变慢但表和索引没有任何变更”的情况最后都是跑一遍ANALYZE TABLE就恢复了。所以遇到这种“无征兆变慢”时先别急着改SQL、加索引检查一下统计信息是不是已经严重失真再做决策。6. 线上巡检与治理慢日志的正确打开方式6.1 慢日志的轮转与保留策略慢日志文件有一个很实际的问题它会不断增长。如果不做轮转一个日活较大的实例积累一个月之后慢日志可能达到几十GB磁盘告警、采集分析都成了负担。推荐的做法是配置系统级的logrotate轮转策略。假设我的慢日志路径是/data/mysql/log/slow.log可以在/etc/logrotate.d/下放一个配置/data/mysql/log/slow.log { daily rotate 30 compress delaycompress missingok notifempty create 660 mysql mysql }含义是每天轮转一次、保留30份、超过30天自动删除并做gzip压缩。这里有两个坑需要提醒一是delaycompress必须先于compress否则MySQL还可能往正在压缩的文件里写日志二是轮转完成后MySQL进程仍持有旧文件的句柄所以create权限要给MySQL用户并且部分情况下需要配合mysqladmin flush-logs或重启实例才能真正切换到新文件。# 手动触发轮转后执行flush-logs让MySQL重新打开日志文件 mysqladmin -u monitor -p flush-logs6.2 建立日常巡检SOP慢日志最有价值的使用方式不是等出问题了再翻而是纳入日常巡检。我自己总结了一套轻量级巡检流程分享出来供参考每日自动跑mysqldumpslow -s c -t 20看一下TOP慢查询列表确认没有新增的“意外SQL”。如果全部是已知的、评估过的SQL直接忽略。每周统计本周慢查询总量变化趋势结合版本发布记录、数据量增长情况尝试解释“为什么这周慢查询变多了/变少了”。每月把慢日志中Rows_examined超过百万的SQL全部捞出来逐一评估是否需要优化。即使它们当前没慢也要列入优化线。告警监控慢日志文件大小的增速。如果日志文件异常膨胀往往意味着系统出现了大量未使用索引的查询或瞬时高并发慢SQL需要立刻介入。6.3 慢日志里几乎不出现的“遗珠”最后想提一个反向场景有一些SQL慢查询但慢日志里始终看不到它们。最典型的就是只读副本上的大查询。很多团队用一主多从架构主库负载不高慢日志里干干净净但某个从库上跑着大量的报表查询、数据分析SQL这些SQL在从库上大量消耗IO和CPU导致从库延迟升高。如果你只盯着主库的慢日志这个问题永远发现不了。所以要记得每个实例的慢日志要分开看从库的慢日志可能比主库更有分析价值。另一个容易被漏掉的是“短连接风暴”——应用频繁创建和销毁连接时每条SQL都不慢但连接建立、鉴权、销毁的过程占用了大量CPU这类问题慢日志同样无能为力得靠SHOW GLOBAL STATUS LIKE Threads_created和连接监控去发现。我在实际工作里养成的一个习惯是每当从应用侧接到“数据库慢”的反馈第一反应不是去重启实例也不是盲目清缓存而是首先把慢日志打开如果还没开的话然后顺着时间戳反向找2-3分钟内的慢SQL再结合监控曲线看是CPU瓶颈、IO瓶颈还是锁等待。绝大多数时候问题都隐藏在那几条被记录下来的语句里。把慢日志用熟练了数据库性能排查这件事你就已经掌握了七成的主动权。