2023 年我维护一个订单服务,后面接的是 MySQL。上线几个月后,服务开始偶尔卡顿——接口响应时快时慢,高峰期尤其明显。我判断是某些 SQL 慢了,得把它们揪出来。第一版我做得很顺手:登上数据库,把慢查询日志打开,long_query_time 设成 10 秒,心想超过 10 秒的 SQL 总该是有问题的,过几天来翻翻日志,慢 SQL 就都躺在里面了。我心里很笃定:慢查询日志嘛,不就是个开关——打开它、设个阈值,慢的 SQL 自己会进去,我用眼睛翻一翻就知道哪里慢了。可等我真去定位问题,一串麻烦冒了出来。第一种最先把我打懵:几天后我去翻日志,文件几乎是空的,只有零星几条;我把 long_query_time 改成 0,想着"全记下来总行了吧",结果第二天日志涨了好几个 G,打开一看密密麻麻几十万行,完全无从下手。第二种最难缠:日志里同一条业务 SQL,因为 WHERE 里的 user_id、时间参数不一样,被记成了成千上万条"不同"的查询,我根本没法知道到底是哪一类查询在拖后腿。第三种最离谱:我把日志里单次最慢的那几条都优化了,数据库还是卡——后来才发现真正的元凶,是一条单次只要 80 毫秒、远低于阈值、所以从来没进过慢查询日志的 SQL,它一秒被调用三千次,总耗时碾压一切。第四种最莫名其妙:日志记下一条慢 SQL,只告诉我它执行了 12 秒,却没告诉我它扫了多少行、用没用上索引,我还是不知道该从哪下手。我盯着这一连串问题想了很久,才彻底想明白:第一版错在一个根本的认知上。我以为慢查询日志就是一个开关:打开它、设一个阈值,凡是执行时间超过阈值的 SQL 就会被自动记下来,我过段时间去翻翻这个日志文件,慢的 SQL 就一条条躺在里面、等着我去优化;阈值嘛随便设个差不多的数,日志嘛就是个纯文本文件、用眼睛翻就行。可这个认知是错的。慢查询日志不是一份"翻一翻就能定位问题"的结论,它是一份原始数据——一份未经聚合、未经统计、还带着一个巨大盲区的原始记录。它只按"单次执行时间"这一个维度去过滤,所以那些"单次很快、但被调用千万次"的查询,它一条都不会记,可正是这种查询常常才是数据库压力的真正大头。它把同一类查询的成千上万次执行打散成成千上万条孤立的记录,你不把它们按"SQL 指纹"重新聚合起来,就永远看不清"哪一类查询"才是问题。它记下的每一条,也不只是一句 SQL,而是一组诊断字段——执行时间、锁等待时间、扫描行数、返回行数——你不会读这组字段,就算找到了慢 SQL 也不知道它为什么慢。所以用慢查询日志定位问题,根上不是"打开开关、翻日志"这两个动作,而是一整套工程:要搞清楚它到底记了什么、有哪几个关键开关;要把阈值当成一道"筛子"来精心调;要把几十万行原始日志按 SQL 指纹聚合成几十类查询的画像;要意识到它的盲区、用 performance_schema 去补上"单次快但总量大"这一块;还要把整个分析例行化、监控起来。本文从头梳理:为什么"打开开关翻日志"会出事,慢查询日志到底记的是什么,阈值该怎么定,日志怎么按 SQL 指纹聚合,"单次慢"和"总量大"为什么是两回事,以及一些把慢查询分析做扎实要避开的工程坑。
问题背景
先把慢查询日志这件事说清楚。慢查询日志(slow query log)是 MySQL 提供的一个功能:你设一个时间阈值 long_query_time,数据库在执行每一条 SQL 时都会计时,凡是执行时间超过这个阈值的,就把这条 SQL 连同它的执行时间、锁等待时间、扫描行数、返回行数等信息,追加写到一个日志文件里。它的本意,是帮你发现那些"跑得慢"的查询。第一版的错,不在于"用了慢查询日志",而在于它把这份日志当成了一个"结论"——以为打开开关、日志里出现的就是答案、用眼睛翻一翻就能定位问题;可它其实只是一份"原料":一份未经聚合、未经统计、还带着一个结构性盲区的原始记录。把原料当成结论,正是第一版所有麻烦的根。
错误认知是:慢查询日志是个开关,打开它、设个阈值,慢 SQL 自己会进去,翻一翻就能定位问题。真相是:它是一份原始数据,要按 SQL 指纹聚合成统计、要按总耗时而非单次耗时来看,而且它有一个盲区——只抓单次慢的、抓不到单次快但高频的。把这一点摊开,第一版的几类问题就都能解释了:
- 阈值难调:设 10 秒日志几乎是空的,设 0 一天涨几个 G、几十万行翻不动。
- 同类查询被打散:参数不同的同一条 SQL 被记成上千条,看不出哪类查询是问题。
- 优化错了对象:单次最慢的几条优化完仍卡,真凶是单次快但高频、从不进日志的 SQL。
- 只知道慢不知道为何慢:日志说一条 SQL 跑了 12 秒,却没读懂扫描行数这些字段。
所以让慢查询定位真正可靠,核心不是"打开开关翻日志",而是一整套工程:读懂日志记的诊断字段、把阈值当筛子精调、按指纹聚合、用 performance_schema 补上盲区、把分析例行化。下面六节,就从第一版"打开开关翻日志"的想当然讲起。
一、为什么"打开开关翻日志"会出事
第一版我定位慢查询的做法,核心就是改两行配置、再用最朴素的办法翻那个日志文件。
# 反面教材:第一版 —— 打开慢查询日志,设个阈值,过几天来翻
# my.cnf 里第一版的配置
# [mysqld]
# slow_query_log = 1
# long_query_time = 10 # 超过 10 秒才记 —— 设得太高
# slow_query_log_file = /var/log/mysql/slow.log
# 几天后,我登上服务器,用最朴素的办法翻这个日志:
def find_slowest_bad(log_path):
entries, block = [], []
with open(log_path) as f:
for line in f:
# 一条记录以 "# Time:" 开头,遇到下一条就把上一条收起来
if line.startswith('# Time:') and block:
entries.append(''.join(block))
block = []
block.append(line)
return entries # 然后靠肉眼一条条去翻、去找最慢的
# 结果:阈值 10 秒,日志几乎是空的;改成 0,日志一天涨几个 G,
# 几十万行根本翻不动;就算翻到几条,同一类 SQL 因为参数不同
# 被记成几千条,我也根本看不出"哪一类查询"才是问题。问题就藏在这段操作"看起来很直接"的假象之下。它隐含了三个极其乐观的假设:阈值随便设一个就能恰好框住"该关注的查询";日志的行数少到人眼能翻得过来;日志里每一行都是一个独立、值得单独看的问题。这三个假设,在你脑子里想象的时候都很自然,可一接触真实的生产数据库,它们一个接一个地碎掉。
这一节要建立的认知是:第一版最深的想当然,是混淆了"一份日志"和"一份分析"这两件完全不同的东西——它以为只要日志文件生成了,定位工作就基本完成了,剩下的只是"打开文件看一眼";可一份日志只是把发生过的事按时间顺序堆在一起的流水账,而定位问题需要的是分析,是把这堆流水账按某种维度归类、统计、排序之后得到的洞察,后者绝不会从前者里自动浮现出来。第一版的脑子里,慢查询日志等于"一个开关加一个文件"。从这个视角看,阈值、聚合、盲区这些都不存在——开关一开,文件里出现的就是答案。可这个视角漏掉了一个最基本的事实:日志是面向"记录"的,而你要的是面向"理解"的。日志忠实地、按时间顺序地记下每一次超过阈值的执行,它做的就是"流水账"这一件事,做得很称职;但它不会、也不该替你判断"这上千条参数不同的记录其实是同一类查询""这一类查询加起来才是大头""这条 12 秒的 SQL 慢在扫描行数上"。这些判断,是"分析"的活,日志不会替你做。第一版把阈值设成 10 秒,日志几乎是空的——这不是"没有慢查询",而是"我把筛子的网眼设得太大,真正该关注的查询全漏过去了";它把阈值设成 0,日志几十万行——这也不是"信息丰富",而是"我把所有流水账原样倒了出来,却没有任何归类,等于没有信息"。无论哪一种,第一版都还停在"我有一份日志"的阶段,而离"我有一份分析"还差着整整一套工程。要跨过这套工程,第一步是先看清楚:这份日志的每一条,到底记了些什么——这是下一节。
二、慢查询日志记的到底是什么:不只是一句 SQL
要用好慢查询日志,先得知道它的每一条记录里到底有什么。很多人以为它就记了一句慢 SQL,其实远不止——它记的是一组诊断数据。
# 慢查询日志里,一条记录长什么样
# Time: 2023-08-14T10:23:01.123456Z
# User@Host: order_app[order_app] @ [10.0.1.5]
# Query_time: 12.348215 Lock_time: 0.000087 Rows_sent: 20 Rows_examined: 4821553
SET timestamp=1692008581;
SELECT * FROM orders WHERE user_id = 88123 AND status = 2 ORDER BY created_at DESC;
# 一条记录里真正有价值的四个数:
# Query_time 这条 SQL 总共执行了多久(秒)
# Lock_time 其中有多久是在等锁,而不是在真正干活
# Rows_sent 最终返回给客户端多少行
# Rows_examined 为了得到结果,引擎一共扫描了多少行 <-- 最关键
#
# 上面这条:返回 20 行,却扫描了 482 万行 —— Rows_examined
# 远远大于 Rows_sent,这几乎总是"索引没用好"的铁证。读懂了一条记录的结构,你才知道还有哪些开关能控制"什么样的查询会被记进来"。慢查询日志的开关,远不止 long_query_time 一个。
# 慢查询日志的关键开关 —— 远不止 long_query_time 一个
# [mysqld]
# slow_query_log = 1 # 总开关:开启慢查询日志
# slow_query_log_file = /var/log/mysql/slow.log
# long_query_time = 1 # 阈值:执行超过 1 秒才记
# log_queries_not_using_indexes = 1 # 没走索引的查询也记(哪怕它快)
# log_slow_admin_statements = 1 # 慢的 ALTER 等管理语句也记
# min_examined_row_limit = 100 # 扫描行数不到 100 的不记
# log_output = FILE # 记到文件(也可设成 TABLE)
# 关键认识:long_query_time 只是"按时间"这一个筛子;
# log_queries_not_using_indexes 是"按是否走索引"的另一个筛子;
# min_examined_row_limit 是"按扫描行数"的又一个筛子。
# 它们一起,决定了"什么样的查询配得上被记一笔"。这一节的认知是:慢查询日志记的从来不是"一句慢 SQL",而是"一次慢执行的现场快照"——SQL 文本只是这张快照里最显眼的一块,真正能告诉你"它为什么慢"的,是 Query_time、Lock_time、Rows_examined、Rows_sent 这几个数字之间的关系;只盯着 SQL 文本,等于拿到了现场照片却只看了照片里的一个角落。第一版翻日志时,眼睛是直接落在 SQL 语句上的——它默认"慢"是 SQL 这句话本身的属性,看到一条 SQL 就想"这句话怎么写得不好"。可"慢"根本不是一句话的属性,它是这次执行在那个时刻、那份数据、那个并发环境下的一个结果,而这个结果的成因,全藏在那几个数字里。Query_time 大,只说明"它确实慢了",这是现象不是原因;真正的原因,要看它慢在哪一段。如果 Lock_time 占了 Query_time 的大半,那这条 SQL 本身可能写得没问题,它只是被别的事务的锁挡在了门外——你去优化这句 SQL 的写法,方向就完全错了,该去查的是谁持有那把锁。如果 Lock_time 很小,而 Rows_examined 是 Rows_sent 的成千上万倍,那原因就清楚地写在脸上:引擎为了挑出这 20 行,硬生生扫了 482 万行,这是典型的"索引没建对或没用上",优化方向是索引。你看,同样是一条 12 秒的慢 SQL,Lock_time 和 Rows_examined 这两个数字,会把你引向两个截然不同的修复方向。第一版因为只看 SQL 文本、不读这组数字,就失去了"分辨慢的成因"的能力,只能笼统地对着 SQL 语句干瞪眼。而那几个开关——log_queries_not_using_indexes、min_examined_row_limit——之所以重要,是因为它们告诉你一件事:long_query_time 不是唯一的筛子,"慢"也不只有"耗时长"这一种定义,"扫描行数巨大""根本没走索引"同样是值得被记一笔的"慢"。理解了一条记录有哪些字段、有哪几个筛子,你才算真正看懂了这份原料。接下来第一个要精调的,就是那个最主要的筛子——阈值,下一节讲。
三、阈值怎么定:long_query_time 不是越小越好
第一版栽的第一个跟头,就是阈值——10 秒太大,0 太小。阈值不该拍脑袋定,它应该建立在"你的查询真实耗时分布"之上。而这个分布,performance_schema 早就替你统计好了。
-- 阈值不该拍脑袋定:先看真实的查询耗时分布,再定阈值
-- performance_schema 里,已经按 SQL 指纹聚合好了每类查询的统计
SELECT
DIGEST_TEXT, -- SQL 指纹(参数已被抽象成 ?)
COUNT_STAR AS exec_count, -- 这类查询执行了多少次
AVG_TIMER_WAIT/1e12 AS avg_seconds, -- 平均耗时(换算成秒)
MAX_TIMER_WAIT/1e12 AS max_seconds -- 最慢的一次(秒)
FROM performance_schema.events_statements_summary_by_digest
ORDER BY avg_seconds DESC
LIMIT 20;
-- 看清分布之后再定 long_query_time:
-- 把它设在"绝大多数正常查询之上、值得你关注的查询之下"。
-- 多数 OLTP 系统,正常查询在几毫秒到几十毫秒之间,
-- 阈值定在 100ms 到 1s 是一个合理的起点 —— 而不是 10s,
-- 更不是 0(那等于关掉了筛子,把全部流水账倒出来)。这一节的认知是:阈值这个东西,本质上是一道筛子的网眼大小,而筛子的全部意义就在于"挡掉一部分、放过一部分";所以根本不存在一个"绝对正确的阈值",只存在"相对于你想看见什么而言,合适或不合适的阈值"——第一版的错,不是把阈值设成了 10 还是 0 这个具体数字,而是它根本没意识到自己是在"配一道筛子",于是随手拨了个数。把阈值想象成淘金的筛子:网眼太大,金沙连同泥沙一起漏光,你什么也淘不到——这就是 long_query_time=10,真正该被关注的、跑了一两秒的查询,全从网眼里漏走了,日志里只剩下那几条极端到 10 秒以上的"巨型沙砾",而它们往往是偶发的、非典型的,代表不了系统的日常压力。网眼太小,泥沙金沙全留在筛子上,你还是得在一堆泥里找金子——这就是 long_query_time=0,等于把筛子撤了,所有查询不分快慢全记下来,几十万行流水账里,有用的信息被无用的信息彻底淹没。一道好的筛子,网眼要恰好卡在"泥沙"和"金沙"的尺寸之间。对慢查询日志来说,"泥沙"是那些跑得飞快、完全正常、多到数不清的查询,"金沙"是那些明显偏离正常、值得你花时间去看的查询。这两者的分界线在哪?它不在你的想象里,它在你数据库的真实数据里——performance_schema 的那张摘要表,已经把每一类查询的平均耗时、最大耗时都算好了,你只要扫一眼,就知道"正常"大概在什么量级、"异常"从哪里开始,阈值自然就该卡在那条缝上。更进一步,阈值还可以是分阶段的:第一阶段你想先抓"最离谱的那批",可以把阈值定得高一点,快速捞出几个大问题;等大问题解决了,再把阈值调低,去看下一个层级的查询。阈值服务于"你这个阶段想看见什么",它是一个会随你的目标而调整的旋钮,不是一个设一次就忘的常量。定好了筛子,留在筛子上的就是值得分析的查询了——可它们此刻还是一条条打散的孤立记录,下一步是把它们聚合起来,这是下一节。
四、日志聚合:把"几十万行"归并成"几十个指纹"
第一版那个"同一条 SQL 被记成上千条"的问题,根子在这里。慢查询日志是按"每一次执行"记录的,可你要分析的对象是"每一类查询"。要从前者得到后者,得先把 SQL 归一化成"指纹"。
# 把 SQL 归一化成"指纹":抹掉具体参数,只留下查询的结构
import re
def fingerprint(sql):
s = sql.strip()
# 1) 字符串字面量,比如 'paid' 'shipped',统统换成 ?
s = re.sub(r"'[^']*'", '?', s)
# 2) 数字字面量,比如 88123、2,统统换成 ?
s = re.sub(r'\b\d+\b', '?', s)
# 3) IN (?, ?, ?, ?) 这种长度不定的列表,统一压成 IN (?)
s = re.sub(r'IN\s*\([^)]+\)', 'IN (?)', s, flags=re.I)
# 4) 多余的空白、换行,压成单个空格
s = re.sub(r'\s+', ' ', s)
return s.lower()
# 优化前:下面这三条,在日志里是三条"不同"的 SQL
# SELECT * FROM orders WHERE user_id = 88123 AND status = 2
# SELECT * FROM orders WHERE user_id = 90011 AND status = 1
# SELECT * FROM orders WHERE user_id = 70345 AND status = 2
# 归一化之后,它们共享同一个指纹:
# select * from orders where user_id = ? and status = ?
# —— 它们终于被认作"同一类查询"了。有了指纹,就能把几十万行日志按指纹聚合,变成几十类查询的画像。聚合的时候,排序方式是关键。
# 按指纹聚合:把几十万行日志,归并成几十个"查询类别"的画像
from collections import defaultdict
def aggregate_slow_log(entries):
# entries: [{'sql':.., 'query_time':.., 'rows_examined':..}, ...]
stats = defaultdict(lambda: {'count': 0, 'total_time': 0.0,
'max_time': 0.0, 'rows_examined': 0})
for e in entries:
fp = fingerprint(e['sql']) # 先算这条记录的指纹
s = stats[fp]
s['count'] += 1 # 这一类查询又出现了一次
s['total_time'] += e['query_time'] # 累加它的总耗时
s['max_time'] = max(s['max_time'], e['query_time'])
s['rows_examined'] += e['rows_examined']
# 关键:按"总耗时"排序,而不是按"单次最慢"排序
return sorted(stats.items(),
key=lambda kv: kv[1]['total_time'], reverse=True)
# 一旦聚合,真相立刻清楚:排在第一的那个指纹,也许单次只要
# 0.3 秒、根本算不上"很慢",但它出现了八万次,总耗时是
# 第二名的几十倍 —— 它才是真正在拖垮数据库的那一类查询。这一节的认知是:聚合的本质,是把分析的单位,从"一次执行"换成"一类查询"——这两个单位之间隔着的,不是一道技术门槛,而是一次视角的根本转变;你优化数据库时真正能动手的对象,从来不是"昨天下午两点零三分那一次执行",而是"orders 表按 user_id 和 status 查这一类查询",而慢查询日志原始的记录方式,恰恰把后者打散成了无数个前者。第一版翻日志时的困惑——"同一条 SQL 怎么有上千条"——其实是一个非常深刻的问题被它当成了一个烦人的细节。日志为什么会把它记成上千条?因为日志记录的单位是"执行",而每一次执行,WHERE 里的 user_id、status 都是具体的值,值不一样,记录看起来就不一样。可对你这个要做优化的人来说,user_id 是 88123 还是 90011,毫无区别——会不会慢,取决于这条查询的"结构"(查哪张表、用哪些列做条件、有没有合适的索引能支撑这个结构),而不取决于代进去的那个具体的值。指纹做的事,就是把"结构相同、只是值不同"的执行,认出来、归成一类——它抹掉值、留下结构,因为结构才是优化的对象。这一步看似只是个字符串替换的小技巧,实则是整个分析的转折点:在它之前,你面对的是几十万条无法比较、无法排序、无法统计的孤立记录;在它之后,你面对的是几十个可以比较、可以排序、可以统计的查询类别。而聚合之后那个排序方式,更是把第一版的另一个错误直接照了出来。第一版的本能是按"单次最慢"找问题——日志里哪条 Query_time 最大就先看哪条。可聚合给了你一个它原本根本算不出来的数字:总耗时,也就是这一类查询的单次耗时累加起来的总和。一旦你能按总耗时排序,你就会看到一个反直觉的景象:那条单次 12 秒、但一天只跑两次的 SQL,总耗时不过 24 秒;而那条单次只要 0.3 秒、却一天跑了八万次的查询,总耗时是 24000 秒。后者对数据库的真实压榨,是前者的一千倍。第一版按"单次最慢"排序,会把全部精力投到前者身上,而后者它甚至看都看不见——为什么看不见?因为那条 0.3 秒的查询,压根就没达到慢查询日志的阈值、从来没被记进日志。这个"看不见",就是慢查询日志的结构性盲区,下一节专门讲它。把这五节连起来,一个查询从执行到最终被你定位,要经过的环节可以画成下面这张图:
[mermaid]
flowchart TD
A[数据库响应变慢] --> B{慢查询日志里有可疑 SQL 吗}
B -->|有| C[把这些慢查询按 SQL 指纹聚合]
B -->|几乎是空的| D[查 performance_schema 指纹摘要表]
C --> E[按这一类查询的总耗时排序]
D --> E
E -->|单次慢 次数少| F[看执行计划 优化这一条的索引]
E -->|单次快 次数极多| G[减少调用次数 或加一层缓存]
F --> H[复查 Rows examined 是否真的下降]
G --> H
五、单次慢 vs 总量大:慢查询日志的盲区
第一版最离谱的那个问题——优化完单次最慢的几条,数据库还是卡——根子就是慢查询日志的这个盲区。它只按"单次执行时间"过滤,所以"单次很快、但被调用千万次"的查询,它一条都不会记。要抓这种查询,必须靠 performance_schema。
-- 慢查询日志的盲区:它只按"单次执行时间"这一个维度过滤,
-- 单次不慢、却被调用千万次的查询,它一条都不会记下来。
-- 要抓住这种查询,必须靠 performance_schema 的指纹聚合表。
SELECT
DIGEST_TEXT,
COUNT_STAR AS exec_count, -- 执行总次数
SUM_TIMER_WAIT/1e12 AS total_seconds, -- 总耗时(秒)
AVG_TIMER_WAIT/1e12 AS avg_seconds, -- 单次平均(秒)
SUM_ROWS_EXAMINED AS total_rows_examined -- 累计扫描行数
FROM performance_schema.events_statements_summary_by_digest
ORDER BY total_seconds DESC -- 按总耗时排,不是按单次
LIMIT 20;
-- 一条 avg 只有 0.05 秒的查询,永远进不了慢查询日志;
-- 可它若被执行了两千万次,total_seconds 就是一百万秒 ——
-- 它对数据库的真实压榨,远远超过那条 12 秒、一天只跑两次的 SQL。要注意,performance_schema 这张摘要表里的数字是"自上次重置以来的累计值"。想看"刚才那十分钟到底发生了什么",得对它做两次快照、相减。
# performance_schema 的指纹表是"累计值",要看某一段时间的
# 负载,得对它做两次快照、相减,得到这段时间内的增量。
def snapshot_digests(conn):
rows = conn.query("""
SELECT DIGEST, DIGEST_TEXT, COUNT_STAR, SUM_TIMER_WAIT
FROM performance_schema.events_statements_summary_by_digest
""")
return {r['DIGEST']: r for r in rows} # 以指纹为键存一份快照
def diff_load(before, after):
# 算出两次快照之间,每个指纹新增的执行次数和总耗时
result = []
for digest, a in after.items():
b = before.get(digest)
d_count = a['COUNT_STAR'] - (b['COUNT_STAR'] if b else 0)
d_time = a['SUM_TIMER_WAIT'] - (b['SUM_TIMER_WAIT'] if b else 0)
if d_count > 0:
result.append((a['DIGEST_TEXT'], d_count, d_time / 1e12))
# 按这段时间内新增的总耗时排序
return sorted(result, key=lambda x: x[2], reverse=True)
# 这样得到的,才是"刚才那十分钟,究竟是哪些查询在压数据库"。这一节的认知是:慢查询日志的盲区,不是一个可以靠"把阈值调得再低一点"来补救的缺陷,它是这个工具的设计原理本身决定的——它的过滤器只有"单次执行时间"这一个维度,而数据库承受的真实压力,等于"单次耗时 乘以 执行次数";慢查询日志只看见了这个乘法里的一个因子,它从结构上就漏掉了另一个因子。这是第一版最值得吸取的一个教训,因为它错得非常隐蔽、非常有迷惑性。第一版做了一件看起来完全正确的事:打开日志,找出单次最慢的几条,逐一优化。它们确实被优化了,日志上单次 12 秒的记录确实消失了。可数据库还是卡。这种"我明明做对了每一步、结果却没改善"的处境,最容易让人怀疑人生。真相是,它每一步的动作都没错,错的是它选择问题的那个"框"——它在"单次很慢的查询"这个集合里穷尽地找,可真正的元凶根本不在这个集合里。元凶是那条单次只要 80 毫秒的查询。80 毫秒,这个数字看一眼就让人放心,它太快了,快到任何人都不会怀疑它——而且它低于任何合理的 long_query_time,所以它从来没在慢查询日志里出现过一次,你翻烂日志也找不到它。可它一秒被调用三千次。把这个乘法做出来:80 毫秒 乘以 三千,就是每秒 240 秒的数据库时间——它一个人,就需要 240 个 CPU 核来扛。它对数据库的压榨,是那条 12 秒 SQL 的成百上千倍,只不过它把这份压榨,拆成了千千万万次"每次都小到不值一提"的执行,均匀地、隐蔽地摊开了。慢查询日志的过滤器,逐次地审视每一次执行,每一次都判定"这次很快,不值得记",于是它一次又一次地放过了真正的元凶。要补上这个盲区,你必须换一个工具——一个不按"单次"过滤、而是按"指纹"把所有执行(无论快慢)都累加统计的工具,这就是 performance_schema 的那张摘要表。它给你的 SUM_TIMER_WAIT,就是那个被慢查询日志彻底无视的"总耗时"。当你学会按总耗时去看负载,那条 80 毫秒的查询就会堂堂正正地排在榜首,再也藏不住。记住:慢查询日志回答的是"哪一次执行慢",而你真正该问的是"哪一类查询最重"——这是两个不同的问题,需要两个不同的工具。理解了这一点,剩下的就是把整套分析做扎实的工程细节,下一节讲。
六、把慢查询分析做扎实,要避开的工程坑
前面五节讲清了慢查询定位的核心:读懂日志字段、精调阈值、按指纹聚合、用 performance_schema 补盲区。但要在生产里真正用稳,还有几个工程坑得专门讲。第一个,是日志本身可能被冲爆——尤其是 log_queries_not_using_indexes 这个开关。
# 坑一:log_queries_not_using_indexes 会把日志冲爆
# 这个开关很有用 —— 它能记下"没走索引"的查询。但在一个
# 有很多小表的库里,小表全表扫描本就不走索引、却也很快,
# 它们会在瞬间把日志刷满。MySQL 给了一个节流阀:
# [mysqld]
# log_queries_not_using_indexes = 1
# log_throttle_queries_not_using_indexes = 60 # 同类每分钟最多记 60 条
# 另外两个常被忽略、却会让你"以为已经记全了"的坑:
# 1) log_output = TABLE 时,过长的 SQL 会被截断,看不全;
# 2) 日志写入本身有磁盘开销,阈值设得过低(比如 0)时,
# 高峰期写日志的 IO 反而会拖慢数据库本身。第二个坑,也是最容易被忽略的:慢查询分析不能"想起来才做一次",它必须例行化、并接上监控告警。
# 坑二:慢查询分析不能"想起来才看一次",要例行化、要告警
ALERT_TOTAL_SECONDS = 600 # 单类查询一个周期内总耗时的告警线
def slow_query_report(conn, top_n=10):
rows = conn.query("""
SELECT DIGEST_TEXT, COUNT_STAR AS cnt,
SUM_TIMER_WAIT/1e12 AS total_s,
AVG_TIMER_WAIT/1e12 AS avg_s
FROM performance_schema.events_statements_summary_by_digest
WHERE DIGEST_TEXT IS NOT NULL
ORDER BY total_s DESC
LIMIT %s
""", (top_n,))
for r in rows:
# 任意一类查询的总耗时冲破告警线,就立刻报警
if r['total_s'] > ALERT_TOTAL_SECONDS:
alert(f"慢查询负载异常: {r['DIGEST_TEXT'][:80]} "
f"次数={r['cnt']} 总耗时={r['total_s']:.0f}s")
return rows
# 每天定时跑一次,把 top 指纹和它们的总耗时画进监控曲线。
# 某个指纹的总耗时曲线突然抬头,往往就是一次性能退化的开端。还有几个坑值得点一下。其一,慢查询日志不要长期开在 long_query_time=0:它对排查问题的那一阵子很有用,但长期全量记录,日志写入的 IO 本身就是一笔不小的开销。其二,定位到一类慢查询后,别急着加索引——先对它跑一次 EXPLAIN 看执行计划,确认它慢在哪,加错索引比不加更糟。其三,Lock_time 占比高的慢查询,问题不在这条 SQL,而在持有锁的那个事务,要顺着锁等待去查别处。下面把慢查询定位常见的几个视角集中对照一下:
慢查询定位:别只盯着"单次最慢的那一条"
看哪个维度 能发现的问题 会漏掉的问题
------------------------------------------------------------
慢查询日志单条 单次执行超阈值的 SQL 单次快但高频的 SQL
按指纹聚合 哪一类查询整体最重 偶发的非典型慢查询
Rows_examined 扫描行数远大于返回行 纯粹的锁等待
performance_schema 全部查询的总耗时排名 被挤出摘要表的旧查询
原则 慢查询日志是原始数据 不是结论
要聚合成指纹 再按总耗时而非单次耗时来排序
这一节这几个坑,串起来是同一个意思:慢查询分析不是一次性的"考古",而是一项需要长期持续的"观测"——数据库的查询负载会随业务增长、随数据量变大、随每一次代码发布而悄悄改变,今天定位准了、优化完了,不等于明天还是这样;你必须把"按指纹聚合、按总耗时排序、盯住头部那几类查询"这件事,变成一条一直跑着、一直画在监控曲线上的例行流程。第一版对慢查询分析的理解,是"出了问题 → 翻一次日志 → 找到并修掉 → 结束"。这是一种"考古"式的心态:把性能问题当成一个已经发生、躺在那里等你去挖掘的遗迹,挖出来、处理掉,事情就完了。可数据库的性能问题不是遗迹,它是活的。慢查询日志会被冲爆这个坑,本质上就是因为负载是活的——你今天觉得 log_queries_not_using_indexes 开着挺好,明天业务上线了一批新的小表查询,日志一夜之间就被刷爆了。监控那个坑更是直接点破了"观测"和"考古"的区别:一次性的翻日志,只能告诉你"此刻"的状况;而性能退化几乎从来不是"此刻"突然发生的,它是一条缓慢上升的曲线——某一类查询的调用次数,随着用户增长每天涨一点;某张表的数据量,随着时间每天大一点,于是原本够用的索引慢慢扛不住了。这种渐变,你"想起来才翻一次日志"是绝对发现不了的,因为你每次翻,看到的都只是一个孤立的点,你看不见这个点正处在一条上升曲线的哪个位置。唯一能抓住渐变的办法,是持续地、例行地度量,把每一类头部查询的总耗时,变成监控面板上一条连续的曲线——这样"缓慢的退化"就不再是无声的,它会表现为曲线上一个看得见的、持续向上的趋势,在它演变成一次线上事故之前,就被你拦下来。把慢查询分析理解成一项需要长期值守的观测工作,而不是一次挖完就走的考古,你才算真正把它做扎实了。
关键概念速查
| 概念 | 说明 |
|---|---|
| 慢查询日志 slow query log | MySQL 把执行时间超过 long_query_time 阈值的 SQL 追加记录到的日志 |
| long_query_time | 慢查询的时间阈值,如一道筛子,设太高会漏记、设太低会让日志爆炸 |
| Query_time | 一条 SQL 的总执行耗时,是慢的现象,不直接是慢的原因 |
| Lock_time | 查询耗时中花在等锁上的部分,占比高说明问题在持锁的事务 |
| Rows_examined | 为得到结果扫描的行数,远大于返回行数几乎总是索引问题的信号 |
| SQL 指纹 digest | 抹掉具体参数后只留结构的 SQL,用于把同类查询聚合成统计 |
| log_queries_not_using_indexes | 记录未走索引的查询,需配节流阀否则小表扫描会刷爆日志 |
| min_examined_row_limit | 扫描行数低于此值的查询不记入慢查询日志 |
| performance_schema | MySQL 内置性能统计,按指纹聚合全部查询而非只记慢的那些 |
| 单次慢 vs 总量大 | 慢查询日志只抓单次慢的,单次快但高频是它的结构性盲区 |
避坑清单
- 不要把 long_query_time 设得太高:10 秒的阈值会让日志几乎为空,漏掉真正该看的查询。
- 不要长期把 long_query_time 设成 0:日志一天涨几个 G,写日志的 IO 还会拖慢数据库。
- 不要用肉眼翻原始日志:几十万行要先按 SQL 指纹聚合成几十类查询再看。
- 不要按"单次最慢"排序找问题:要按"这一类查询的总耗时"排序。
- 不要忽视单次快但高频的查询:它是慢查询日志的盲区,要靠 performance_schema 抓。
- 不要只看 Query_time:Rows_examined 远大于 Rows_sent 才是索引问题的信号。
- 不要无节制开 log_queries_not_using_indexes:小表全表扫描会瞬间刷爆日志,要配节流阀。
- 不要把 performance_schema 的累计值当区间值:要做两次快照相减,取这段时间的增量。
- 不要定位完就直接加索引:先跑 EXPLAIN 确认它慢在哪,加错索引比不加更糟。
- 不要想起来才分析一次:要例行化,把头部指纹的总耗时画进监控曲线并设告警。
总结
回头看第一版那个"打开开关、设个阈值、过几天翻日志"的方案,它的失控很典型。它不在某一行配置,而在一个对慢查询日志的根本误解:以为它是一份"翻一翻就能定位问题"的结论,阈值随便设、日志用眼睛看就行。真相是,慢查询日志只是一份原始数据——它把同一类查询的成千上万次执行打散成成千上万条孤立记录,你不按 SQL 指纹把它们聚合起来,就看不清哪一类查询是问题;它只按"单次执行时间"这一个维度过滤,所以那些单次飞快、却被调用千万次的查询,它一条都不会记,而那种查询常常才是真正的元凶。第一版把原料当成了结论,于是阈值难调、同类查询被打散、优化错了对象、只知道慢不知道为何慢,全都顺理成章。
而把慢查询分析做对,工程量并不小。它不是"打开开关翻日志"那么简单,而是要读懂日志里 Query_time、Lock_time、Rows_examined 这组诊断字段、看清一条 SQL 到底慢在哪;要把阈值当成一道筛子,基于真实的查询耗时分布去精调;要把几十万行原始日志按 SQL 指纹聚合成几十类查询的画像、并按总耗时而非单次耗时排序;要意识到慢查询日志的盲区、用 performance_schema 去抓那些单次快但高频的查询;还要把整套分析例行化、接上监控告警。一套真正可靠的慢查询定位,是这些环节一个不少地拼起来的。
这件事其实很像一家超市想搞清楚"到底是哪类商品最赚钱"。第一版的做法,像是只盯着货架上"单价最高的那几件商品"——一瓶上千元的红酒、一只名贵的火腿,心想最贵的肯定最赚钱。可一个月下来,利润还是上不去。为什么?因为那瓶红酒一个月只卖出两瓶,而真正撑起利润的,是那些单价不起眼、却一天能卖出几千份的矿泉水和面包——它们单件利润薄到你根本不会多看一眼,可乘上那个巨大的销量,总利润碾压一切。一家会经营的超市是怎么做的?第一,它不看单件商品的流水账,而是把所有小票按"商品类别"归类(这就是 SQL 指纹聚合)。第二,它给每一类商品算的是"这个月这一类的总销售额",再按总额排名(这就是按总耗时排序),而不是按单价排名。第三,它还会特别留意那些"连价签都没贴好"的商品(这就是没走索引的查询)。第四,这份销售分析不是一年做一次,而是每天、每周都在滚动地看(这就是例行化监控)。一家超市能不能赚到钱,靠的从来不是"盯住最贵的那几件",而是有没有一套把全部交易聚合、归类、按总额排序的分析方法。慢查询定位也一样:数据库慢在哪,答案从来不在"单次最慢的那一条",而在"按总耗时排名的头部那几类"。
这类问题还有一个共同的麻烦:它在开发和测试时几乎暴露不出来。你本地测,数据库里就那么几万行测试数据,随便什么查询都是几毫秒返回;并发也低,你一个人点几下,根本压不出"单次快但高频"那种总量问题;你也不会专门去翻慢查询日志,因为压根没有什么查询能慢到触发阈值。你测的那几条 SQL 恰好都飞快,你就会觉得"慢查询嘛,真有问题打开日志翻翻就行"。真正会把问题撑爆的,是上线后的真实环境:真实的表是几百万、几千万行起步的,会让一条没建好索引的查询从几毫秒劣化成十几秒;真实的并发会把那条"单次只要 80 毫秒"的查询每秒调用几千次,把它的总耗时放大到碾压一切;真实的业务每天都在增长,会让今天还够用的索引,几个月后悄悄扛不住。这些场景,你本地那几万行数据、那一个人的点击,一个都模拟不到。所以如果你正在维护一个数据库,别等服务卡到用户来投诉、别等优化完单次最慢的几条却发现毫无改善,才回头怀疑你当初那套"翻翻日志"的办法。在你打开慢查询日志的第一时间就想清楚:这个阈值该卡在哪、日志该怎么按指纹聚合、该按总耗时还是单次耗时排序、那些单次飞快却高频的查询该用什么去抓、这套分析该怎么例行地跑下去——把"让慢查询日志生成出来"和"让它真正帮你定位到问题"当成两件必须分别去做的事,这是这篇文章最想留给你的一句话。
—— 别看了 · 2026