ARTICLE DETAIL

资讯详情

深耕商务建站与企业官网运营的一线实战洞察。

MySQL慢查询日志全解析:从开启配置到EXPLAIN优化实战

MySQL慢查询日志全解析:从开启配置到EXPLAIN优化实战 1. 慢查询到底是什么为什么你必须关注它第一次接手线上MySQL数据库的时候我最头疼的事不是别人问MySQL怎么安装而是深更半夜收到一条警报CPU飙升、接口超时、用户开始骂人。翻遍代码找不到问题最后打开慢查询日志一眼就看见那条该死的SQL——三张表join一张表几百万行数据连索引都没有一次查询跑了几十秒。从那以后我就养成了一个习惯接手任何数据库第一件事就是确认慢查询日志有没有开没开就先开上再谈别的。很多人觉得慢查询日志是事后诸葛亮出了问题才去翻。这个想法大错特错。慢查询日志的价值恰恰在于提前发现——它不是在你已经故障的时候才出现而是每天都把那些执行时间超标的SQL悄悄记下来等你有空的时候去翻一翻就能提前发现那些现在还不致命、但数据量一涨就会爆炸的隐患。我见过太多案例一个小查询在十万行数据时跑50毫秒没人管等数据涨到一千万行的时候变成5秒直接拖垮整个业务。慢查询日志的意义就是让你在50毫秒的时候就注意到它而不是等到5秒才被迫处理。那到底什么叫慢查询MySQL的定义很简单凡是执行时间超过long_query_time阈值的SQL语句都会被记录到慢查询日志里。默认情况下这个阈值是10秒但说实话10秒这个值在互联网业务里太奢侈了一般我建议线上业务改成1秒甚至更低。注意这里说的执行时间不光是SQL本身执行的时间还包括锁等待、排序、回表这些环节的耗时也就是说一条SQL从开始执行到返回结果的完整时间。慢查询日志解决的核心问题就两个第一知道哪些SQL慢第二知道它们慢在哪。前者靠日志记录后者靠执行计划分析。这篇文章我会从怎么开启慢查询日志开始一步步讲到怎么读日志、怎么用工具聚合分析、怎么用EXPLAIN定位瓶颈最后分享一些我在实际运维中踩过的坑。无论是刚入门的DBA、后端开发还是自己折腾服务器的博主这篇文章都值得你从头到尾看一遍因为慢查询排查这活儿不管你用什么数据库中间件、什么云平台思路永远是通用的。2. 开启慢查询日志的正确姿势2.1 先看当前状态——别急着改配置接手一台MySQL服务器第一件事永远都是先查现状而不是直接改参数。我用得最多的就是这组命令SHOW VARIABLES LIKE slow_query_log; SHOW VARIABLES LIKE slow_query_log_file; SHOW VARIABLES LIKE long_query_time; SHOW VARIABLES LIKE log_queries_not_using_indexes;这四个参数是慢查询日志的四大核心配置。slow_query_log是开关ON就是开着slow_query_log_file是日志文件路径long_query_time是时间阈值单位是秒支持小数比如0.5就是500毫秒log_queries_not_using_indexes记录那些没走索引的查询。这里有个细节很多人容易搞混long_query_time的判定从MySQL 5.1开始就是超过这个值才记录等于不算是严格大于的关系。另外在MySQL 5.1.6之前还有个log_long_queries参数老版本用的现在早就废了看到网上老教程里出现就别照着抄了。还有一个坑是slow_query_log_file指定的目录。MySQL进程要有权限写这个文件否则日志起不来或者写一半卡住。常见的情况是用了默认路径但那个分区磁盘满了慢查询日志写不进去你还在那傻等。我给个建议把这个文件放到独立的数据盘目录下跟数据目录分开这样就算日志暴增也不会拖垮系统盘。2.2 临时开启与永久开启两种方式都要会临时开启是针对当前实例的重启MySQL后配置就丢了。这种方式适合你只是想临时排查问题不想动配置文件-- 临时开启慢查询日志 SET GLOBAL slow_query_log ON; -- 设置阈值 SET GLOBAL long_query_time 1; -- 记录没有走索引的查询 SET GLOBAL log_queries_not_using_indexes ON;注意一点SET GLOBAL改的是全局值但对当前已经存在的连接不生效。也就是说你改了之后新发起的连接才会用新值之前那些连接还是老配置。如果你想对当前会话也生效得加上SET SESSION。这个细节在实际操作中非常容易踩我曾经就是改了全局阈值结果测试客户端用的是长连接跑了半天发现日志里一条都没记还以为是配置出了问题实际上是会话级参数没跟上。永久开启需要修改配置文件my.cnfLinux或my.iniWindows在[mysqld]段落里加上[mysqld] # 开启慢查询日志 slow_query_log 1 # 日志文件路径建议用绝对路径 slow_query_log_file /var/log/mysql/mysql-slow.log # 阈值1秒线上业务建议这个值往下调 long_query_time 1 # 记录未使用索引的查询 log_queries_not_using_indexes 1 # 限制日志文件大小避免撑爆磁盘5.7支持这个参数 slow_query_log_file_size 1073741824改完之后重启MySQL服务生效。不过这里要提醒你生产环境尽量别动不动重启我一般做法是先用SET GLOBAL在线开启然后再改配置文件等下次维护窗口重启的时候自然永久生效。这样既不间断业务又能保证配置最终落盘。2.3 阈值到底设多少才合理long_query_time设置多少合适这个问题没有标准答案得看你的业务场景。我见过最极端的一个案例有个团队把所有SQL都设为阈值0结果慢查询日志每分钟几十万条直接把磁盘打爆了。也见过一个传统企业项目阈值设成20秒等于什么都没记录。我个人的经验是分场景来定业务场景建议阈值原因高并发互联网业务0.5秒~1秒接口响应要求快超过1秒已经影响用户体验一般企业应用1秒~2秒容忍度稍高但慢SQL仍需记录离线分析/数仓5秒~10秒大批量跑数几百毫秒不现实日常排查初期先1秒逐渐下调避免第一天日志量太大吓到自己还有一点log_queries_not_using_indexes这个开关我建议在开发环境开着生产环境要看情况。它在MySQL 5.6之后有个变化不是所有没走索引的查询都会被记录比如全表扫描的行数小于一定阈值时不会记。而且这个开关产生的日志量极大生产环境如果没有专人盯日志容易被大量无效记录淹没反而看不清真正的问题。我一般是开发环境开启线上谨慎开启或者关闭。3. 慢查询日志里到底记了什么——读懂每行内容3.1 日志字段逐一拆解开启慢查询日志之后过一段时间你就能看到类似这样的内容# Time: 2024-06-15T10:23:45.123456Z # UserHost: root[root] localhost [127.0.0.1] Id: 812345 # Query_time: 2.345678 Lock_time: 0.001234 Rows_sent: 100 Rows_examined: 1000000 # Thread_id: 8 Schema: orders Last_errno: 0 Killed: 0 # InnoDB_trx_id: 18875 SET timestamp1718442225; SELECT o.order_id, u.user_name, p.product_name FROM orders o LEFT JOIN users u ON o.user_id u.user_id LEFT JOIN products p ON o.product_id p.product_id WHERE o.status pending ORDER BY o.create_time DESC LIMIT 100;这段日志信息量很大一个一个说。Query_time是查询总耗时这是你判断SQL是否超时的直接依据Lock_time是锁等待时间如果这个值很高说明SQL在等待其他事务释放锁问题未必在SQL本身的执行效率上Rows_sent是实际返回给客户端的行数Rows_examined是这条SQL为了返回结果而扫描过的行数——这个数值是重中之重Rows_examined和Rows_sent的差距越大说明扫描了大量行却只返回了少量行典型的索引问题或者查询逻辑问题。SET timestamp...这行在日志里容易被忽略但它很重要。因为慢查询日志里记录的SQL是后补的如果你直接复制SQL执行得到的执行计划和当时会有差异。SET timestamp让你知道这条SQL当时执行的时间点配合监控系统就能还原当时的服务器状态。3.2 日志格式MySQL 5.7和8.0的差异MySQL 5.7默认的慢查询日志格式是文本格式可读性好但解析起来麻烦。MySQL 8.0引入了log_output参数设置日志输出格式可以是FILE文本文件、TABLE记录到mysql.slow_log表或者两者都写。我建议生产环境用FILE格式理由有两个一是文件格式可以用各种现成工具分析二是表格式写入本身有开销高并发下会影响性能。log_outputTABLE的场景也有就是当你需要直接用SQL查询慢查询记录时很方便比如SELECT * FROM mysql.slow_log ORDER BY start_time DESC LIMIT 10;但说实话我用得很少还是文件格式加工具分析最顺手。MySQL 8.0里还有一个long_query_time支持微秒级别的设置比如0.000100表示100微秒不过日常用不到这么细。3.3 日志会记录哪些SQL不会记录哪些SQL慢查询日志记录的是执行完成的SQL。也就是说如果一条SQL因为锁等待超时、被客户端取消或者其他原因导致没有执行完成它不会被记录。这是一个很容易被误解的点——你以为慢查询日志能捕获所有卡住的查询实际上它只捕获慢但最终执行完的查询。那些被kill掉的、陷入死锁的SQL还得靠其他手段排查比如performance_schema里的事件记录。另外慢查询日志记录的是DML语句SELECT、UPDATE、DELETE、INSERT等预编译语句也会记录比如PreparedStatement方式执行的SQL会记录对应的语句文本。但存储过程内部执行的SQL在存储过程级别不会被记录除非内部SQL本身超时了才会记录那条SQL。管理类语句像CREATE INDEX、ALTER TABLE这种DDL操作虽然也耗时但默认情况下不记录在慢查询日志里。这点经常让人迷惑——你明明在凌晨跑了两个小时的ALTER TABLE加索引慢查询日志里却什么都没有。MySQL 5.7开始有个log_slow_admin_statements参数可以控制是否记录这种管理语句建议需要分析DDL耗时时把它开开。4. 慢查询日志别用眼睛看工具才是亲爹4.1 日志一多就抓瞎先学会用mysqldumpslow慢查询日志开了一段时间后文件可能是几百MB甚至几个GB。这时候你如果还是用tail -f或者less一页页翻效率极低。MySQL自带了mysqldumpslow工具专门用来汇总分析慢查询日志。它的基本用法很简单# 查看日志里最慢的10条SQL mysqldumpslow -s c -t 10 /var/log/mysql/mysql-slow.log参数说明-s是指定排序方式c代表按执行次数计数排序t是返回前N条al是平均锁等待时间at是平均查询时间。我常用的是# 按平均查询时间排序看最慢的20条 mysqldumpslow -s at -t 20 /var/log/mysql/mysql-slow.log # 按执行次数排序看哪些SQL被频繁执行且耗时 mysqldumpslow -s c -t 20 /var/log/mysql/mysql-slow.logmysqldumpslow有个很聪明的设计它会自动归一化SQL。什么叫归一化就是把SQL里的具体值替换成抽象的占位符。比如SELECT * FROM users WHERE id 10086; SELECT * FROM users WHERE id 10087;这两条在工具看来是同一类SQL会合并统计。这样你看到的就是某类慢查询的总共执行次数、平均耗时、最大耗时而不是被几千条相似SQL淹没。不过mysqldumpslow也有局限它只支持基本统计看不到SQL执行计划的细节而且对复杂的多表查询、子查询归一化处理得不算好。正常情况下我拿它做第一轮筛选找出嫌疑SQL然后再对每一条单独做EXPLAIN分析。4.2 pt-query-digest慢查询分析的终极武器要说慢查询日志分析工具里哪个最能打那必须是Percona Toolkit里的pt-query-digest。这个工具比mysqldumpslow强太多了它不仅能分析慢查询日志还能分析通用日志、二进制日志。安装Percona Toolkit的方式各个系统不一样Ubuntu上是sudo apt-get install percona-toolkitCentOS上需要先配置Percona的yum源再安装这里不展开。装好之后分析慢查询日志的姿势pt-query-digest /var/log/mysql/mysql-slow.log输出结果分三大块。第一块是总体报告包括分析时间段、SQL总数、唯一SQL数、总耗时、最长耗时等。第二块是按查询类型分组的排名会列出每个查询组的执行次数、总耗时、平均耗时、占比默认按总耗时排序。第三块是每个查询组的详细profile展示该组SQL的响应时间分布、归一化后的SQL文本、示例SQL等。这个工具最厉害的地方在于它会把所有SQL按指纹分组这个指纹是基于SQL文本生成的哈希值跟mysqldumpslow的归一化类似但更精细。你一眼就能看出哪类SQL消耗了数据库80%的时间然后重点针对它优化。用pt-query-digest还有一个场景我特别推荐对比分析。比如大促前后分别收集一个慢查询日志然后用工具的--review选项对比两次的差异就能知道哪些SQL的耗时在大促期间恶化最严重。这个功能在容量规划和限流策略制定时非常有价值。4.3 没有Percona Toolkit时怎么办——纯SQL查询方案有些环境不让装第三方工具或者你觉得装重量级工具不划算。没关系还有土办法。MySQL 5.7可以把慢查询日志输出到表里然后直接用SQL分析-- 开启表格式输出 SET GLOBAL log_output TABLE; SET GLOBAL slow_query_log ON; -- 按执行次数排序看高频慢SQL SELECT LEFT(SUBSTRING(sql_text, 1, 50), 30) AS sql_prefix, COUNT(*) AS cnt, ROUND(AVG(query_time), 2) AS avg_query_time, MAX(query_time) AS max_query_time FROM mysql.slow_log GROUP BY sql_prefix ORDER BY cnt DESC LIMIT 20;不过我得说这种方法的分析能力有限只能做初步统计。而且mysql.slow_log表引擎是CSV查询效率感人数据量大了会越来越慢。所以它只适合救急真正的高效分析还得靠文件格式加专业工具。5. 从发现慢SQL到定位瓶颈——EXPLAIN实战解读5.1 一条慢SQL的标准分析流程日志发现了慢SQL复制到测试库怎么一步步找到问题根源我的标准动作是第一步看SQL本身搞清楚它是干什么的涉及哪些表逻辑是否合理。第二步用EXPLAIN看执行计划。第三步分析每个表的访问方式、关联顺序、扫描行数。第四步结合索引情况和数据分布验证。第五步改写SQL或者加索引。EXPLAIN的用法很简单就是在SQL前面加上EXPLAIN关键字EXPLAIN SELECT o.order_id, u.user_name, p.product_name FROM orders o LEFT JOIN users u ON o.user_id u.user_id LEFT JOIN products p ON o.product_id p.product_id WHERE o.status pending ORDER BY o.create_time DESC LIMIT 100;执行后你会得到一张表重点关注这么几个列type访问类型从好到差依次是system、const、eq_ref、ref、range、index、ALL。看到ALL就说明在做全表扫描这是最常见的慢查询根因。key实际用到的索引如果为空说明没走任何索引。rows预估扫描的行数这个数是优化器估计的不一定精确但量级很有参考价值。Extra这一列信息量巨大看到Using filesort说明需要文件排序看到Using temporary说明用了临时表看到Using where说明索引条件下推不充分。还是用上面那个例子如果EXPLAIN结果显示orders表的type为ALL预估扫描100万行那问题就很明显了WHERE o.status pending这个条件没有索引可用MySQL只能挨个翻表看看哪行符合条件。再加个ORDER BY o.create_time DESC又触发文件排序双重debuff不慢才怪。5.2 一个完整的优化案例拆解我给你看一个我自己实际处理过的案例。业务反馈某个列表页接口越来越慢最开始50毫秒现在1.2秒还没到警报线但趋势不对。抓慢查询日志找到SQLSELECT id, title, user_id, create_time FROM articles WHERE category_id 105 AND status 1 ORDER BY create_time DESC LIMIT 10;EXPLAIN结果type: ref key: idx_category rows: 23456 Extra: Using where; Using filesort表面看起来走了idx_category索引不算太差为什么慢仔细分析category_id 105这个分类下有两万多行然后还要在结果里过滤status 1再按create_time排序最后取10条。问题就出在这里——索引只过滤了分类没有同时处理状态和排序导致MySQL查完两万多行后还要做文件排序当然快不起来。优化方案是建一个联合索引ALTER TABLE articles ADD INDEX idx_cat_status_time (category_id, status, create_time);注意索引列的顺序有讲究等值条件的列放前面这里是category_id和status排序字段create_time放最后。这样设计的原因是MySQL可以用这个索引同时完成过滤和排序避免Using filesort。优化后EXPLAIN变成type: ref key: idx_cat_status_time rows: 186 Extra: Using index condition扫描行数从两万多降到186行接口耗时从1.2秒回到30毫秒。这个案例就是说慢SQL排查不能只满足于走了索引要看索引是否真的覆盖了查询的所有需求。5.3 索引没生效的几种常见原因索引建了但没用上这是比没建索引更让人头疼的情况。我总结了几个常见原因隐式类型转换。如果字段是VARCHAR类型SQL里写WHERE user_id 12345数字MySQL会隐式把字符串转成数字导致索引失效。正确写法是WHERE user_id 12345。对索引列使用函数。WHERE DATE(create_time) 2024-06-15会让索引失效因为MySQL要先对每一行的create_time执行DATE函数才能比较。正确做法是WHERE create_time 2024-06-15 00:00:00 AND create_time 2024-06-16 00:00:00。前导模糊查询。WHERE title LIKE %MySQL%百分号在最前面的模糊匹配没法用索引只能全表扫。这个没有特别好的索引解法如果确实有需求考虑全文索引或者搜索引擎。联合索引不满足最左前缀原则。建了(a, b, c)联合索引但查询条件只用到b和c不包含a索引失效。优化器选择不用索引。这也是一种情况你以为MySQL会走索引但优化器经过成本估算认为全表扫描更快比如数据量很少或者要回表的行数占比太高比如超过20%~30%。这种情况有时候可以通过FORCE INDEX强制走索引但我不建议直接这么干更健康的做法是优化SQL本身的逻辑或者更换索引设计。排查索引问题最实用的工具是EXPLAIN之外再配合SHOW WARNINGS。执行完EXPLAIN后再加一句SHOW WARNINGSMySQL会告诉你它实际重写后的SQL长什么样方便对照。6. 慢查询的治理闭环——从发现到预防6.1 日志只是起点要建立问题跟踪机制很多团队开了慢查询日志之后就再也不管了三个月后日志文件几个GB但没有任何人看过。这是典型的开了个寂寞。我建议是形成一套循环每日采集 → 每周分析 → 每季度治理回顾。每日采集可以靠定时任务比如每天凌晨跑一次pt-query-digest把结果输出成当天报告存到固定的目录。每周抽时间看一周汇总挑出Top 10耗时组织开会讨论。新增慢SQL要登记优化完要验证没优化完的要放进待办池。这套机制看起来简单但真正坚持下来的团队不多。很多人的思维是业务不报障就不管等业务方找上门来的时候往往已经是用户都感知到卡顿的阶段了。我觉得做技术的应该有这种主动出击的觉悟。6.2 结合监控平台实时告警日志分析是事后行为实时告警才能防患于未然。现在主流做法是把MySQL的SHOW GLOBAL STATUS里的指标或者performance_schema的数据采集到Prometheus这类监控平台配上Grafana做可视化看板。关键的告警项有这么几个告警指标建议阈值说明慢查询数每分钟超过基线值3倍观察趋势突然增长往往是SQL性能退化或数据量突增单条SQL最大耗时超过3秒直接告警尤其是核心交易链路全表扫描次数持续上升可能有新SQL没建索引或索引被误删Threads_running经常超过50数据库连接池打满的前兆实时监控的一个难点是阈值怎么定。我建议是先从半年的慢查询日志里算出每天的平均数和P95值再用这个做基线。不要拍脑袋定一个1秒因为不同业务差异太大。6.3 推荐一套我常用的慢查询巡检脚本我把自己日常巡检用的一个Shell脚本简化后放在这里逻辑很简单每天跑一次把当天的慢查询日志分析结果邮件发给自己或者写到指定文件里周末再汇总。#!/bin/bash LOG_DIR/var/log/mysql SLOW_LOG${LOG_DIR}/mysql-slow.log REPORT_DIR/var/log/slow_report TODAY$(date %Y%m%d) mkdir -p ${REPORT_DIR} # 用pt-query-digest分析当天的慢日志 pt-query-digest ${SLOW_LOG} --since 24h ${REPORT_DIR}/report_${TODAY}.txt # 取Top 5输出到单独文件 pt-query-digest ${SLOW_LOG} --since 24h \ --limit 5:95:1 ${REPORT_DIR}/top5_${TODAY}.txt # 统计当天慢查询总量 slow_count$(grep -c ^# Query_time: ${SLOW_LOG}) echo Date: ${TODAY} SlowQueries: ${slow_count} ${REPORT_DIR}/summary.txt这个脚本你可以用crontab每天凌晨跑一次0 2 * * * /usr/local/bin/slow_query_analyze.sh脚本运行完之后早上上班第一件事就是随手翻一下报告看看昨天有没有新的慢SQL冒出来。养成这个习惯之后你会发现线上SQL的性能问题基本都能在爆发之前被扼杀在摇篮里。7. 那些年我踩过的坑——慢查询日志的隐秘角落7.1 参数改了不生效的连环坑慢查询日志相关参数有全局和会话之分这是最基础的坑。但更隐蔽的坑是MySQL 8.0里SET GLOBAL设置了slow_query_log之后如果配置文件里写的是slow_query_log OFF重启之后会被配置文件覆盖回去。你以为永久开启了实际上重启之后又关了。这种问题在日志文件上看不出来直到某天发现慢查询日志突然不更新了才察觉。解决方法是改完配置文件后必须验证一遍用SHOW VARIABLES确认所有相关参数的实际值。我自己有个习惯改完配置之后写一条慢SQL故意触发一下然后去看日志文件有没有新增记录。这个验证动作只要几秒钟能省掉后面无数排查时间。7.2 磁盘满导致日志写不进去慢查询日志默认会无限增长如果不做日志轮转迟早占满磁盘。磁盘满了MySQL会怎么样不会崩溃但会拒绝写操作造成写入阻塞这比慢查询本身更严重。我在生产环境见过最惨的一次就是慢查询日志直接把根分区写满所有业务写入全部卡死最后不得不删日志紧急恢复。我的处理经验是三层防护。第一日志文件和数据库数据目录分开别放在同一个分区。第二用logrotate做日志切割按天或者按大小轮转保留最近7天。第三开启slow_query_log_file_size限制单个文件大小超过自动轮转。这三层都做到基本不会出大问题。7.3 不要忽视锁等待时间高的慢查询有时候Pull出来的慢SQLQuery_time很高但Rows_examined并不大执行计划也走了索引。这时候问题很可能不在SQL本身而在Lock_time上。Lock_time高说明SQL大部分时间在等待锁释放。怎么验证看慢查询日志里Lock_time和Query_time的比值。如果Lock_time占了大头你需要排查其他并发事务。特别是线上业务用了SELECT ... FOR UPDATE、UPDATE、DELETE这类会加锁的语句在高并发场景下容易互相阻塞。这时候光优化SQL没用得从业务层下手比如减小事务范围、减少锁的持有时间、用乐观锁代替悲观锁。7.4 慢查询日志记录的是因还是果最后讲一个我自己的理解。很多人一看到慢查询日志里某条SQL耗时5秒就认定这条SQL是性能问题的根源急着改写SQL。但慢查询日志记录的只是表象真正的因可能是它执行时的系统状态——比如当时服务器负载本来就高磁盘IO饱和CPU被打满任何SQL执行都会变慢。所以分析慢查询日志时一定要结合当时的时间点和监控数据来看。如果某条SQL平时执行很快只有特定时间段才慢那要考虑的不光是SQL本身还有服务器的资源竞争、定时任务冲突、备份作业并发等问题。慢查询排查是一个系统性的工作不能只盯着SQL文本而要把它放到整个运行环境里去理解。8. 最后一个老运维的心里话做了这么多年数据库运维我越来越觉得慢查询排查这事儿真正考验人的不是工具用得有多熟练而是你有没有一套完整的思路。日志开没开、阈值合不合理、看到慢SQL之后能不能快速定位到索引问题和锁问题、优化完之后有没有持续跟踪验证每一步都环环相扣。我个人最深的体会是慢查询日志不是用来背锅的而是用来帮团队提前发现隐患的。它记录的每一条慢SQL都是数据库在告诉你我这儿有个地方快撑不住了你有空来修一下。你认真对待它它能帮你把很多故障消灭在萌芽状态你无视它它就会在某个深夜给你一个大惊喜。如果你现在还没有开启慢查询日志今天就动手开起来阈值设成1秒然后把日志分析工具装上。一个月后再回头看你会感谢当时的这个决定。
返回列表
PREV
查看更多资讯
NEXT
返回资讯列表