2207 字
约 7 分钟
20
S08-A12 · 持久层的 SQL 观测:日志、慢查询与规则

一次线上慢查询排查花了三小时。可用的信息只有应用日志里的一行"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. 自测

  1. 三个观测入口分别记什么?"模板 vs 实际"这个差别为什么决定了它们的用途不同?
  2. 为什么耗时必须与影响行数成对记录?两者各自指向什么方向?
  3. long_query_time 应该按什么设?设太小与设太大各有什么后果?
  4. 语句模板归一化的最干净做法是什么?"直接记带参数的 SQL"损失了什么能力?
  5. 为什么慢查询告警应盯趋势而不是绝对值?
  6. 判断"观测是否足够"的那个问题是什么?
S08-A12 · 持久层的 SQL 观测:日志、慢查询与规则
https://www.clxhxhhr.top/posts/6418/
作者
clxstart
发布于
2024-12-31
许可协议
CC BY-NC-SA 4.0
评论
0 条
还没有评论,先写一条吧。