一次线上慢查询排查花了三小时。可用的信息只有应用日志里的一行"query timeout",没有 SQL 文本、没有参数、没有耗时分布。最后靠时间点排查与代码搜索拼出了那条语句——而这本来应该是日志里现成的信息。
持久层的观测是多数系统里最薄弱的一环:应用日志记了"出错了",但没记"执行了什么"。补上这一环不需要复杂的工具,只需要决定三件事——记什么、记在哪、什么时候记。
1. 三个观测入口
| 入口 | 内容 | 用途 |
|---|---|---|
| 应用侧日志 | 实际执行的 SQL 与参数、耗时 | 归因到具体代码 |
| 数据库慢查询日志 | 服务端视角的执行耗时与扫描行数 | 归因到数据库资源 |
采集侧统计(如 performance_schema) |
语句模板的聚合耗时 | 找出高频慢语句 |
三者还对应三种不同的时间尺度:应用侧是逐次记录(有全量也有采样),数据库慢日志是超过阈值的记录,统计表是累计归因。排查用前两者,治理用第三者——混用会得出错误结论。
三者的差别在"模板 vs 实际":慢查询日志记的是带参数的具体语句,而统计表记的是归一化后的模板。排查时需要前者,做治理时需要后者。
2. 应用侧该记什么
| 字段 | 为什么 |
|---|---|
| 语句模板(参数用占位符) | 可聚合、不泄敏 |
| 参数值(脱敏后) | 复现问题所需 |
| 耗时 | 归因与分布 |
| 影响行数 | 判断是扫描还是命中 |
| 调用点(类+方法) | 直接定位代码 |
这五个字段构成的最小集合,还可以再加两个可选字段:连接/数据源标识(多数据源时必需)与是否命中缓存(判断这次查询是不是真的到了库)。后者在缓存层之上的系统里尤其有用。
第三项与第四项必须成对:只看耗时会误判。一条 SQL 耗时 800ms 但只返回 1 行,和耗时 20ms 却扫了 10 万行,两者的优化方向完全相反。
// 记录"模板 + 参数 + 耗时 + 行数"四件套,缺一不可
long start = System.nanoTime();
try (var rs = ps.executeQuery()) {
int rows = 0;
while (rs.next()) rows++;
long ms = (System.nanoTime() - start) / 1_000_000;
if (ms > SLOW_MS || rows > ROWS_WARN) {
log.warn("sql.slow template={} params={} cost_ms={} rows={} at={}",
template, maskedParams, ms, rows, callSite);
}
}
脱敏要保留"形状"而不是清空:把字符串参数替换成长度相同的占位符、数字参数保留位数。这样既不能还原敏感值,又能看出"这次参数是超长的那个"。
// 脱敏保留形状:能判断参数特征,无法还原原值
String mask(Object v) {
if (v instanceof CharSequence s) return "*".repeat(Math.min(s.length(), 32));
if (v instanceof Number n) return String.valueOf(n).replaceAll("\\d", "0");
return "<obj>";
}
// 例:'张三' → '**',12345678 → '00000000'
注意 template 与 params 分开:合并成一个字符串会让聚合与脱敏都变难。
3. 慢查询日志的正确打开方式
| 参数 | 建议 | 说明 |
|---|---|---|
slow_query_log |
开 | 常态化开启,不要临时开 |
long_query_time |
从应用侧 P99 的两倍起 | 与业务感知对齐 |
log_queries_not_using_indexes |
谨慎开 | 会产生大量噪音 |
min_examined_row_limit |
设一个下限 | 过滤小表扫描 |
第二项的判据是"业务能感知到的慢",不是"数据库觉得慢"。设成 0.1 秒会淹没在噪音里,设成 10 秒会漏掉真正影响用户的查询。
第三项在有大表全扫的系统里会产生海量日志,实际做法是只在排查期临时开,而不是常态开启。
// 临时开启未走索引记录,排查完立即关闭
SET GLOBAL log_queries_not_using_indexes = ON;
SET GLOBAL min_examined_row_limit = 5000; -- 只记扫描超过 5000 行的
-- 排查结束后
SET GLOBAL log_queries_not_using_indexes = OFF;
4. 语句模板归一化
要把"同一类慢语句"聚合出来,必须先把参数替换成占位符。
| 做法 | 效果 | 风险 |
|---|---|---|
| 正则替换数字与字符串 | 简单有效 | 可能过度归一 |
| 用预编译语句的原始 SQL | 天然归一 | 依赖实现 |
| 哈希后聚合 | 省存储 | 无法回读原文 |
| 保留前 200 字符做键 | 折中 | 长语句截断相同 |
第二种最干净:预编译语句在构造时就有一份带 ? 的模板,直接记它,不需要解析。
-- 从 performance_schema 取高频慢模板(服务端视角)
SELECT DIGEST_TEXT, COUNT_STAR, ROUND(AVG_TIMER_WAIT/1e9,1) AS avg_ms,
SUM_ROWS_EXAMINED, SUM_ROWS_SENT
FROM performance_schema.events_statements_summary_by_digest
ORDER BY SUM_TIMER_WAIT DESC LIMIT 20;
-- SUM_ROWS_EXAMINED / SUM_ROWS_SENT 的比值是"扫描效率",比耗时更能指出问题
慢日志的读法也有讲究:先按"扫描行数"排序,再按耗时排序。扫描行数大而耗时小的,通常是小表的全扫(无害);扫描行数大且耗时大的,才是真正要处理的。
5. 有了观测之后的三条规则
| 规则 | 阈值来源 |
|---|---|
| 单语句扫描行数上限 | 业务可接受的响应时间倒推 |
| 同类模板的耗时趋势告警 | 周环比而非绝对值 |
| 未走索引的语句清单 | 定期导出并分配处理 |
第二条值得展开:慢查询告警应当盯趋势。绝对值会随数据增长而漂移,趋势反映的是"新引入了慢语句"。周环比上升 20% 比"超过 500ms"更有意义。
6. 排错:五种"日志里有但查不出"
| 现象 | 成因 | 处理方向 |
|---|---|---|
| 只有超时没有 SQL | 只记了异常没记语句 | 记录模板与参数 |
| 定位不到代码 | 没记调用点 | 记类名+方法名 |
| 无法复现 | 参数被脱敏成空 | 脱敏保留形状 |
| 聚合不出来 | 直接记了带参数的语句 | 记模板 |
| 日志量过大 | 全量记录 | 只记慢的与扫描多的 |
聚合的产物可以直接变成治理清单:
// 每周导出的三类清单,各分配给对应 owner
1. 扫描/返回比 > 100 的模板 → 索引或查询写法问题
2. 新出现且耗时的模板 → 近期代码引入,优先处理
3. 调用次数高但耗时中等的模板 → 高频小慢,加缓存或改写
第四项是最常见的浪费:把带具体参数的 SQL 打进日志,等于放弃了聚合能力。每条语句都是"唯一的",统计不出"哪一类慢"。
7. 边界:什么情况不必上观测
| 场景 | 为什么 | 做法 |
|---|---|---|
| 极小系统(单表、低频) | 问题可直接看 | 不开慢日志 |
| 只读报表库 | 不影响在线 | 只记资源占用 |
| 一次性数据修复 | 有明确时间窗 | 临时开日志 |
| 已有 APM 自动采集 SQL | 无需重复 | 直接用 APM |
还有一条与成本有关的边界:观测本身有代价。全量记录 SQL 会让日志量上涨数倍,磁盘与采集成本随之上升。折中做法是"采样 + 慢的全记":正常语句按 1% 采样,超过阈值的全记——这样既保留分布,又不丢掉异常。
判断口径一句话:出问题时,你能否在十分钟内拿出那条 SQL。拿不出,就说明观测缺失;拿得出,就不必再加。
8. 自测
- 三个观测入口分别记什么?"模板 vs 实际"这个差别为什么决定了它们的用途不同?
- 为什么耗时必须与影响行数成对记录?两者各自指向什么方向?
long_query_time应该按什么设?设太小与设太大各有什么后果?- 语句模板归一化的最干净做法是什么?"直接记带参数的 SQL"损失了什么能力?
- 为什么慢查询告警应盯趋势而不是绝对值?
- 判断"观测是否足够"的那个问题是什么?