跳到主要内容

生产慢 SQL，为什么总定位不到是谁执行的？

· 阅读需 6 分钟

生产环境慢SQL日志只告诉你哪条SQL慢，不告诉你谁执行的。MyBatis/JPA/JdbcTemplate全缺业务调用栈，DLZ-DB用一行配置自动打印调用方，5分钟定位到代码行。

系列第 2 篇 · 上篇说到 MyBatis 的日志不告诉你 SQL 谁执行的，这篇展开聊这个问题。

一、问题：日志告诉你"有 SQL 慢"，不告诉你"谁让它慢"​

凌晨三点，监控告警：

[慢SQL] 耗时: 3520ms
SELECT * FROM sys_menu WHERE parent_id = ? AND status = ? ORDER BY sort ASC

打开日志，全局搜 sys_menu，出来 47 条相似记录。哪条是罪魁祸首？是菜单加载、权限校验、还是某个定时任务？没人知道。

MyBatis 的日志长这样：

DEBUG - ==>  Preparing: SELECT * FROM sys_menu WHERE parent_id = ? AND status = ?
DEBUG - ==> Parameters: 0(Long), 1(Integer)
DEBUG - <==      Total: 128

只告诉你"发生了什么"，不告诉你"在哪里发生的"。

这不是 MyBatis 一家的问题——JPA、JdbcTemplate、Hibernate 默认的 SQL 日志，全都缺少业务调用栈。

二、核心解决思路：把"业务调用方"和"SQL 执行"绑在一起输出​

定位慢 SQL 的本质需求是：从一条 SQL，反查到调用它的那行业务代码。

要实现这个，无非两条路：

  1. 拦截 SQL 执行的瞬间，回溯当前线程的调用栈，找到第一个非框架类
  2. 在调用入口埋点，把业务上下文塞进 ThreadLocal/MDC，SQL 输出时一起带出来

不管走哪条路，目标都一样：让日志里直接出现 MenuController.java:42 这种可点击跳转的位置信息。

三、业界一般方法​

方法 1：人肉 grep + 经验​

最常见，也最痛苦。

grep "sys_menu" app.log | grep -B 2 "WARN"

依赖于：业务代码里恰好有日志、关键字唯一、问题能复现。线上偶发问题基本破不了。

方法 2：MyBatis Plugin / Interceptor​

写一个 Interceptor 拦 Executor.query：

@Intercepts({@Signature(type = Executor.class, method = "query", args = {...})})
public class SqlCallerPlugin implements Interceptor {
    public Object intercept(Invocation invocation) throws Throwable {
        String caller = findBusinessCaller();
        log.info("[caller:{}] sql executing...", caller);
        return invocation.proceed();
    }
}

需要理解 MyBatis 内部生命周期、@Intercepts 的签名规则、不同版本兼容性。写对了能用，但门槛不低。

方法 3：p6spy 代理 DataSource​

p6spy 把整个 DataSource 包一层代理，拦截所有 JDBC 调用。

spring:
  datasource:
    url: jdbc:p6spy:mysql://...
    driver-class-name: com.p6spy.engine.spy.P6SpyDriver

优点：框架无关，MyBatis/JPA/JdbcTemplate 通吃。 缺点：

  • 性能损耗 10-20%（所有 SQL 都经过代理层）
  • 默认输出格式没有调用栈，要自定义 MessageFormattingStrategy
  • 自定义后再加调用栈遍历，又回到方法 2 的复杂度

方法 4：APM 工具（SkyWalking、Pinpoint、Arthas）​

最强大，能看到全链路调用。但：

  • 部署门槛高，需要 agent + 后端服务
  • 小项目用着重，相当于杀鸡用牛刀
  • 排查时还要登录另一个平台，跳转链路长

方法 5：日志 MDC 手动埋点​

每个 Controller / Service 入口塞 MDC：

MDC.put("requestId", UUID.randomUUID().toString());
MDC.put("caller", "MenuController.list");

输出格式里加 %X{caller}。靠人记得埋点，漏一处就断链。

四、DLZ-DB 的解法：一个开关，零侵入​

DLZ-DB 选了方法 1（运行时栈遍历），把它做成框架内置能力。

一行配置开启​

dlz-db:
  show-caller: true
  slow-sql-threshold: 1000   # 超过 1000ms 自动 WARN

日志直接带定位​

caller:(MenuController.java:42) 3520ms sql:SELECT * FROM sys_menu t where parent_id = 0 and status = 1 order by sort asc
  • IDE 里 Ctrl+点击 MenuController.java:42 直接跳转到代码行
  • 参数已经填充进 SQL，拷贝就能去数据库执行验证
  • 慢 SQL 自动用 WARN 级别输出，告警系统直接抓

为什么 DLZ-DB 能这么做？​

核心在 DbLogUtil.getTraceCaller(int level)——遍历当前线程的调用栈，跳过框架类，第一个业务类就是调用方：

    /**
     * 取得调用者
     */
    public static String getTraceCaller(final int level) {
        StackTraceElement[] trace = new Throwable().getStackTrace();
        int index = level;
        if (index < 1) {

逻辑朴素到难以置信：new Throwable().getStackTrace() 拿到栈，跳过 com.dlz.db.*、java.*、org.springframework.*，第一个剩下的就是你的业务代码。

第一次拿到后写进 MDC 缓存（KEY_CALLER），同一次请求里多条 SQL 共享同一个 caller，栈遍历只跑一次，性能开销几乎可以忽略。

性能对比​

方案性能损耗是否需要额外组件
p6spy10~20%是（驱动层代理）
MyBatis Plugin1~3%否，但要写代码
APM agent3~10%是（agent + 后端）
DLZ-DB show-caller<1%否

栈遍历只在第一次 SQL 输出时跑一次，后续 SQL 直接读 MDC 缓存。

五、实战：5 分钟定位慢 SQL​

某次线上告警：

[慢SQL] caller:(OrderService.java:85) 2300ms
sql:SELECT * FROM order_item WHERE order_id in (1,2,3,...,999)

操作流程：

  1. 点击 OrderService.java:85 → 跳转到代码
  2. 看到是 findItemsByOrders(List<Long> orderIds) 一次塞了 999 个 ID
  3. 改成分批查询（每批 100 个）
  4. 响应时间从 2300ms 降到 120ms

整个过程不需要 grep、不需要猜、不需要问"这 SQL 谁写的"。

总结​

好的日志不是告诉你"发生了什么"，而是告诉你"在哪里发生的"。

定位慢 SQL 的方案有很多，从原始的 grep 到重型的 APM 都能用。但对一个中小项目来说，零侵入、零依赖、一个配置开关才是性价比最高的选择。

DLZ-DB 把"生产可排查"这件事做成了框架默认能力，而不是让你自己去搭。这是它和 MyBatis 在设计优先级上最大的差异。

下一篇：为什么简单 CRUD 也要建 6 个文件？