页面卡成 PPT,慢日志却一条没有:MySQL 慢查询排查现场
周四下午三点十七分运营群里弹出一段录屏。订单列表页翻到后面几页转圈转圈还在转圈。八秒后超时。底下跟着一句「小陈 这个页面是不是坏了」小陈是有经验的页面卡八成有条慢 SQL。他登上服务器熟练地敲tail-100/var/log/mysql/slow.log空的。一整天一条记录都没有。页面明明在转圈日志却干干净净。这时候人会开始自我怀疑是不是根本不该查数据库是前端渲染慢是网关是网络抖动还是……玄学隔壁工位的老周端着保温杯凑过来扫了一眼屏幕问了一句「你阈值设的多少」一、空日志不代表没慢查询代表你的线画得太高了小陈查了一下SHOWVARIABLESLIKEslow_query_log;-- 是否开启SHOWVARIABLESLIKElong_query_time;-- 阈值默认 10 秒SHOWVARIABLESLIKEslow_query_log_file;-- 日志落在哪long_query_time10。默认值从来没人动过。老周喝了口水「你想想一条 SQL 要跑满 10 秒才被记一笔。真有这种东西你的连接池早就满了服务早挂了还轮得到你翻日志」真正天天折磨用户的是那些 0.5 秒、1.2 秒、3 秒的查询。它们不触发任何告警不会让服务挂掉只是让页面「有点卡」——然后在流量高峰期几万次这样的「有点卡」叠在一起把数据库压趴。慢查询是一个阈值概念不是绝对概念同一条 SQL在阈值 10 秒的库里根本不算慢在阈值 100 毫秒的库里就是重点关照对象。慢不慢是你自己划的那条线说了算。线画在 10 秒等于宣布「我只关心已经出人命的」。生产环境的线通常画在100 毫秒到 1 秒SETGLOBALslow_query_logON;SETGLOBALlong_query_time1;-- 单位秒支持小数比如 0.1小陈改完回原来那个会话一试——还是没记录。他愣了两秒正准备说「这参数是不是坏了」老周先开口了两个坑新手基本全踩①long_query_time对已经建立的连接不生效。你得新开一个连接再测否则会觉得「改了没反应」。②SET GLOBAL只在本次运行期有效。MySQL 一重启配置就打回原形。要永久生效必须写进my.cnf/my.ini的[mysqld]段——不然下次出故障你又会对着一个空日志怀疑人生。新开连接重刷订单页。日志「哗」地一下有东西了。二、四个字段就能给这条 SQL 定性# Time: 2026-07-31T15:23:45.123456Z # UserHost: app[app] 10.0.0.5 [] Id: 12345 # Query_time: 3.521872 Lock_time: 0.000132 Rows_sent: 20 Rows_examined: 1000020 SET timestamp1753957425; SELECT * FROM orders ORDER BY id LIMIT 1000000, 20;字段看着一堆真正用来定性的只有四个字段含义怎么看Query_time总执行耗时秒超过阈值才会出现在这里Lock_time其中等锁的时间逼近Query_time→ 问题在锁不在 SQL 本身Rows_sent实际返回给客户端的行数很大 → 取了太多数据Rows_examined服务器实际扫描的行数核心指标老周用笔在便签上圈了两个数Rows_sent: 20—— 最后只给客户端送回了20 行Rows_examined: 1000020—— 为了这 20 行服务器翻了一百万零二十行。「五万比一。」他把便签推过来「你要 20 条它翻了一百万条。慢在哪还用问吗」这就是LIMIT 1000000, 20的真实行为。MySQL 不会魔法般地一步跳到第一百万行——它会老老实实取出前 1000020 行然后把前一百万行扔掉。书没拿错流程也没出错就是做了一百万次无用功。这种写法有个专门的名字深分页。记住这一句后面全都能挂回来慢查询的根因几乎总是「扫描行数 ≫ 返回行数」。后面你会遇到的所有术语——索引失效、回表、深分页、typeALL、执行计划里的rows——描述的都是同一件事为了拿一点点数据翻了太多不需要的行。顺手记住一句判断口诀先看Lock_time排除锁问题再看Rows_examined / Rows_sent的比值。这条日志的Lock_time只有 0.13 毫秒说明它没在排队等锁三秒半全花在自己身上。比值越大优化空间越大如果比值已经接近 1 却还是慢那多半不是「找得慢」而是返回的数据量本身就大或者卡在排序、临时表这些额外开销上。三、别修那条最惨的去修那条最烦的阈值调低之后新问题来了慢日志开始疯长一天几万行。小陈翻着翻着眼睛一亮——他找到一条Query_time: 8.7的报表导出 SQL。八秒七这不就是元凶吗老周瞟了一眼「它一天跑几次」「……三次。」「那你修它干嘛。」嫌疑人单次耗时每天次数一天总共吃掉A · 报表导出8.7 秒3 次约26 秒B · 订单列表0.5 秒10 万次约14 小时A 看起来触目惊心B 才是那个每天默默吃掉十四个小时数据库时间的家伙。所以关键是按「总耗时」聚合排序不是按「单次耗时」找最惨的那条。MySQL 自带的工具就够用# 按总耗时排序取前 10 条mysqldumpslow-st-t10/var/log/mysql/slow.log# 按出现次数排序抓高频惯犯mysqldumpslow-sc-t10/var/log/mysql/slow.log-s指定排序依据t总耗时、l总锁时间、r总返回行数、c出现次数加a前缀表示取平均比如at-t N取前 N 条。它有个很关键的行为把 SQL 里的具体参数值抽象成N和S。这样WHERE id 1和WHERE id 2会被归成同一个模板统计——否则十万次调用散成十万条不同记录你什么规律都看不出来。装了 Percona Toolkit 的话pt-query-digest更好用pt-query-digest /var/log/mysql/slow.logreport.txt它直接按总耗时占比排序会明确告诉你「排第一的这个 SQL 模板吃掉了全部慢查询时间的 43%」还附带耗时分布95 分位、最大最小值。线上排查首选。二八法则在这里特别明显通常20% 的 SQL 模板贡献了 80% 的慢查询总耗时。先修排在最前面的那两三条收益最大。别一头扎进那条最长、但一天只跑一次的报表 SQL。四、拿到元凶接着问「它为什么慢」聚合出 Top SQL下一步就是EXPLAIN看 MySQL 到底打算怎么找数据用哪个索引、预计扫多少行、有没有额外开销。对照信号基本能归到下面某一类成因典型信号没索引 / 索引失效typeALL、keyNULL深分页LIMIT偏移量巨大、Rows_examined爆炸回表太多命中行很多且Extra里没有Using index排序落磁盘Extra: Using filesort用了临时表Extra: Using temporary常伴GROUP BY/DISTINCTJOIN 被驱动表没索引多表 join某张表typeALL返回数据量本身大Rows_sent很大、习惯性SELECT *锁等待Lock_time逼近Query_time表结构有问题字段类型过大、宽表、缺合适的联合索引其中最常见的是「索引失效」。而且十有八九不是没建索引是写法让索引用不上在索引字段上套函数WHERE DATE(created_at) 2026-07-31隐式类型转换varchar列传了个数字进去前缀模糊匹配LIKE %关键词联合索引不满足最左前缀这几种写法的共同点是索引明明就摆在那儿MySQL 却只能放弃它回到一行一行翻的老路——又绕回了那句「扫描行数 ≫ 返回行数」。最容易被跳过的一步改完要复测加完索引一定要重新EXPLAIN确认它真的走上了再实际跑一遍看耗时。优化器是按估算成本选路的它不一定采纳你新建的索引。你以为的优化可能压根没生效。五、故事还有另一半不是 SQL 的锅订单页的问题定位完了。小陈正准备收工隔壁测试同学探过头来「那个……我点保存按钮也很慢八九秒才有反应你顺便看看」小陈很自信地去慢日志里搜——阈值都调到 1 秒了嘛。又什么都没搜到。老周这次直接笑出声「你以为的慢日志和它真正记的东西不是一回事。」long_query_time不包含锁等待时间它只统计 SQL真正执行的时间等锁的时间单独记在Lock_time里。所以一条「被别人的事务挡了 8 秒、自己只跑了 0.01 秒」的 SQL在阈值 1 秒下根本不会进慢日志。这就是排查时最容易误判的场景用户喊慢慢日志干干净净于是你开始怀疑网络、怀疑前端、怀疑人生。其实它在排队而门口那本登记簿只记录「进屋之后待了多久」不记录「在门外站了多久」。类似的「SQL 本身没毛病但就是慢」还有几种情况表现锁等待Lock_time高SQL 完全正常它只是在排队Buffer Pool 命中率低同一条 SQL 时快时慢——数据不在内存就得去读磁盘大事务长时间不提交一片 SQL 同时变慢长事务撑大版本链拖累 MVCC服务器资源打满所有 SQL 一起慢CPU / IO / 连接数到顶了主从延迟只有读库慢或者读到了旧数据这里有个决定排查方向的分岔口值得单独刻在脑子里「全部 SQL 一起变慢」和「某一条 SQL 慢」是两种完全不同的故障。前者先查机器资源、锁、长事务后者才去查这条 SQL 的执行计划。方向搞反会浪费大量时间——拿着EXPLAIN逐条分析一个其实是磁盘打满的故障分析到天亮也得不出结论。六、如果此刻正在卡呢慢查询日志是事后分析工具。要是现在线上就正卡着、老板站在你身后用另外两招。看当前正在跑什么SELECTid,user,host,db,command,time,state,infoFROMinformation_schema.processlistWHEREcommand!SleepANDtime5ORDERBYtimeDESC;time是已经跑了多少秒state告诉你它卡在哪个阶段Sending data、Locked、Copying to tmp table……。确认某条就是元凶、业务上也允许可以KILL id先止血。看历史统计完全不依赖慢日志开关SELECTdigest_text,count_star,ROUND(avg_timer_wait/1e12,3)ASavg_sec,sum_rows_examined,sum_rows_sentFROMperformance_schema.events_statements_summary_by_digestORDERBYavg_timer_waitDESCLIMIT10;MySQL 5.7 之后还有sys库封装好的现成视图读起来更省事SELECT*FROMsys.statements_with_full_table_scansLIMIT10;-- 做过全表扫描的 SQLSELECT*FROMsys.statement_analysisLIMIT10;-- 综合分析这条路的好处是哪怕慢日志压根没开、阈值高得离谱它照样能告诉你哪些语句扫得最多、跑得最久。七、把这一下午串成一条链路逼近 Query_time很小开启慢查询日志阈值设 0.1~1 秒跑一段时间攒数据聚合分析按总耗时排序先看 Lock_time锁问题去查锁与长事务看 Rows_examined / Rows_sentEXPLAIN 看 type / key / rows / Extra归因: 索引失效 / 深分页 / filesort / join对症改写或加索引再 EXPLAIN 实测验证注意最后一箭头是拐回去的。这是个闭环不是一条直线——线上数据量天天在涨今天不慢的 SQL明年可能就是新的 Top 1。临走前老周还补了一句有个参数专门用来提前抓「定时炸弹」。log_queries_not_using_indexes ON它会记录所有没走索引的 SQL哪怕它现在只要 2 毫秒。因为表里现在只有一千行全表扫当然快等它涨到一千万行同一条 SQL 就是一场事故。配合log_throttle_queries_not_using_indexes限制每分钟记录条数免得日志被刷爆。八、这一路踩过的坑打包带走❌阈值直接设成 0 想「记全部」→ 日志暴涨写日志的 IO 自己就把数据库拖垮了❌只看Query_time不看Lock_time→ 把锁等待误判成 SQL 写得烂改半天 SQL 一点用没有❌逐条翻日志不做聚合→ 抓到偶发的长尾漏掉真正的高频惯犯❌SET GLOBAL改完忘了写配置文件→ 重启后配置蒸发下次故障又是一个空日志❌改完参数不新开连接→ 以为参数坏了其实是老连接不生效❌慢日志是空的就宣布数据库没问题→ 大量 0.5 秒的 SQL 在 1 秒阈值下全是隐形的❌加完索引不复测→ 优化器可能压根没选它写在最后那天下午小陈最大的收获不是学会了几个参数而是明白了一件事空日志一直在说实话只是他问错了问题。整个慢查询定位压缩成三句话慢是相对的——先把阈值划到有意义的位置问题才会现形根因几乎总是「扫描行数 ≫ 返回行数」——先看Lock_time排除锁再用Rows_examined / Rows_sent定性最后用EXPLAIN归因定位和优化是两件事——先说清「它为什么慢」再谈「怎么改」。顺序反过来就变成了凭感觉加索引然后祈祷。大多数看起来玄乎的数据库性能问题拆开之后都只是这一句为了拿到一点点数据翻了太多不需要的行。