做后端测试的兄弟应该都有过这种经历接口突然慢了好几秒DBA从数据库翻出来的慢查询日志里躺着一条SQL但看完日志你根本不知道这个SQL是谁调起来的。测试环境更是如此流量本来就少慢查询半天不出现等它出现的时候眼前又是一堆没有上下文的信息接口名、业务操作、代码路径全靠猜。我前段时间为了解决这个事换了一个思路——不依赖数据库的慢查询日志而是在应用层用插桩技术做了一套方法级耗时监控顺手把接口、方法、SQL执行关系全部串起来。这套方案不侵入业务代码测试环境随时可以启动对排查慢查询那个阶段特别实用。1. 项目背景与核心思路拆解1.1 慢查询测试到底难在哪先说痛点。大家平时遇到接口响应慢第一反应就是去数据库看慢查询日志但数据库慢查询日志的局限非常明显它只有SQL文本、执行时间、锁等待时间这些数据库侧的信息没有应用侧的调用方信息。你看到一条select * from order_item where order_id ?执行了500ms但这条SQL是哪个接口发起的、哪段代码循环调用的、当时的业务参数是什么日志里全都没有。这就导致你只能拿着SQL去代码仓库里搜搜出来十几处相似的写法还得靠猜。测试环境复现难是另一个大头。测试环境通常没有生产那么大的流量慢查询的产生本身就带着很强的随机性和缓存命中率、并发量、数据量都有关。你手工点页面点半天可能一次都触发不了。就算触发了单次慢查询的观测窗口就那么几秒等你想去看日志日志已经刷过去了。还有一个经常被忽略的点接口慢不一定等于SQL慢。我处理过一个典型case接口总耗时3秒多但数据库慢查询日志里最慢的一条SQL才跑了600ms。后来一查是代码里循环调了20多次外部HTTP接口每次100多毫秒累积出来的。这种情况下你盯着慢查询日志看再久也找不出真正的根因。这些问题凑到一起就会让慢查询测试变成一件靠经验和运气的事情。所以我才想到用插桩技术在应用层直接埋一个“探针”把每次接口请求的完整执行过程记录下来。1.2 为什么说插桩技术是解决这类问题的一把钥匙插桩技术翻译成大白话就是在程序运行的关键路径上插入一段观察代码用来采集运行时的数据。它可以做到在不修改业务代码的前提下给系统装上一堆“监控探针”。放到慢查询测试这个场景里插桩的价值体现在四个方面第一它能统计方法级别的耗时让你直接看到“哪个方法慢”而不是面对一条孤零零的SQL。比如我可以统计到OrderServiceImpl.queryPage这个方法花了3秒再往下一层看到OrderMapper.selectOrderPage花了2.8秒一层层往下追根因范围能缩小到具体的类和方法。第二它能记录上下文信息。插桩的时候可以顺手把请求ID、参数摘要、调用栈一起打到日志里这样每条慢查询都能对应到具体的业务请求。第三动态生效不需要重新部署系统。Java的Agent机制可以在JVM启动时加载也可以运行时attach到已启动的进程这意味着测试环境下你想什么时候开监控就什么时候开不用为了排查一个问题去重启服务。第四开关可控。插桩代码可以设计成只记录超过阈值的调用平时对业务几乎无感知测试用例该怎么跑就怎么跑。用个生活化的类比数据库慢查询日志像是路口装的监控摄像头只能拍到车流量插桩技术则像是给每辆车装了行车记录仪不仅记录速度还记录司机踩油门和刹车的时间点可以完整还原行车过程。1.3 整体方案设计这套方案的核心是三层插桩加一个贯穿全链路的请求ID。第一层是接口入口层通常对应Controller或者REST接口入口记录请求路径、请求参数和总耗时。第二层是业务逻辑层对应Service层的核心方法记录业务逻辑的耗时分布。第三层是数据库访问层对应Mapper、DAO或者底层JDBC调用记录SQL执行耗时和参数信息。通过请求ID把这三层日志串起来就能还原出一张完整的调用链哪个接口慢→里面哪个业务方法慢→最终落到了哪几条SQL上。请求ID可以在网关或过滤器中生成然后塞进ThreadLocal里整个请求处理过程中各个插桩点都能取到。整体设计并不复杂但实践下来效果非常好。下面我会从原理讲到落地把代码和踩坑都分享出来。2. 插桩核心原理与选型思路2.1 插桩技术的基础原理从字节码说起Java代码经过编译之后会变成.class文件里的字节码JVM在类加载时再把字节码翻译成机器指令执行。插桩做的事情就是在类加载这个环节“动手脚”利用Java的Instrumentation机制在字节码被JVM加载之前对其进行修改向目标方法的前后插入计时和记录逻辑。这里有几个技术栈需要认识一下java.lang.instrumentJDK自带的Instrumentation API是Java Agent的标准入口。ASM一个直接操作字节码的底层库性能最好但需要你对JVM指令有一定了解。Byte Buddy在ASM之上做了高层封装API对普通人友好很多。我用得最多的是它写几行代码就能实现方法级别的拦截。Javassist也可以通过API修改字节码上手相对简单但有同学反馈性能略逊于ASM。市面上很多APM工具像SkyWalking、Pinpoint这类链路监控产品核心实现的底层思路也是字节码插桩只是它们会把数据上报到专门的服务端做聚合展示。我们要做的轻量方案原理相同只是数据自己落文件、自己分析灵活度和可控性都更高。2.2 为什么不用AOP或手动埋点很多同学会问Spring AOP也能做方法耗时统计为什么非得用Java Agent这种看起来有点“重”的方案这里要如实对比一下。Spring AOP的Around确实能拦截方法并统计耗时但它的适用范围是Spring容器管理的Bean而且需要提前开发好切面逻辑。如果测试临时发现某个类特别慢而这个类恰恰没有配置切面你还得改代码、重新部署这就违背了“快速排查”的初衷。手动埋点就更不靠谱了。在每个方法开头写一行long start System.currentTimeMillis();结尾再来一行打印短时间内是能定位问题但测试环境往往不止一次排查慢查询代码里 accumulates 一堆临时日志排查完还得记得清理忘记清理就会污染代码库。三种方式的对比表如下方式代码侵入程度生效方式可监控范围实用成本手动埋点高得改代码重新部署看埋点位置低但脏Spring AOP切面中要提前配置切面仅限Spring管理的Bean低Java Agent插桩低启动参数或运行时attach几乎所有类和方法中但一劳永逸Java Agent插桩的最大优势就是“无侵入”。业务代码一行都不用改测试人员维护一个独立的Agent项目打包成jar后挂在服务的启动参数上就行。2.3 工具链选型自研还是用现成APM可能也有人会问既然SkyWalking、Arthas这些现成工具都能做方法级追踪为什么还要自己搞一套Arthas确实好用watch和trace命令能在秒级定位到慢方法特别适合人工在线排查。但Arthas的本质是一个交互式诊断工具它没法像测试平台那样无人值守地跑一段时间然后把所有慢查询统一落库生成报告。你得守在终端前面一条条命令地敲数据也不太好做批量聚合。SkyWalking这类APM平台的功能则过于完整。要享受它的完整能力通常得部署Agent、后端存储、控制台一条链路测试环境如果没有现成设施为了一个慢查询排查去搭建整套平台性价比太低。所以我的建议是自研一个轻量Java Agent只做“方法耗时SQL耗时请求ID”这三件事。自研的另外一个重要理由是扩展灵活。测试环境的需求和线上APM的需求不完全一样。测试时你经常要临时加一个监控点比如发现某个方法最近特别可疑想看看它内部调用了哪些SQL——自研Agent改改匹配规则就能做到现成工具反而不太容易定制。3. 实操过程搭建一套慢查询插桩采集链路3.1 准备环境与依赖先准备一个普通的Java工程JDK 8以上即可Maven管理依赖。工程本身不用跟被测系统放一起它是独立打包、独立维护的。pom.xml里需要引入两个核心依赖Byte Buddy和Byte Buddy Agent。dependencies dependency groupIdorg.bytebuddy/groupId artifactIdbyte-buddy/artifactId version1.14.12/version /dependency dependency groupIdorg.bytebuddy/groupId artifactIdbyte-buddy-agent/artifactId version1.14.12/version /dependency /dependencies另外还需要把打包插件配置成可以生成MANIFEST.MF中带Premain-Class的jar一般用maven-shade-plugin或者maven-assembly-plugin来实现打包时在插件配置里声明主类即可。3.2 Agent入口类实现Agent的入口类需要实现一个premain方法JVM在启动时加载Agent时会自动调用它。在premain里我们通过Byte Buddy定义一个拦截规则。我一般会拦截三类对象后缀为Controller的接口入口类、后缀为Service的业务逻辑类、后缀为Mapper的数据库访问类。public class SlowQueryAgent { public static void premain(String arg, Instrumentation inst) { System.out.println([SlowQueryAgent] premain start); new AgentBuilder.Default() .type(ElementMatchers.nameEndsWith(Controller) .or(ElementMatchers.nameEndsWith(Service)) .or(ElementMatchers.nameEndsWith(Mapper))) .transform((builder, typeDescription, classLoader, module, protectionDomain) - builder.method(ElementMatchers.any()) .intercept(MethodDelegation.to(TimingInterceptor.class))) .installOn(inst); System.out.println([SlowQueryAgent] install finish); } }这段代码的意思是凡是类名以Controller、Service、Mapper结尾的类它里面的所有方法都被拦截拦截逻辑交给TimingInterceptor去执行。用nameEndsWith单纯是为了方便你也可以改成全限定名匹配或者只匹配某个包下的类。3.3 耗时统计拦截器拦截器的核心逻辑是包裹目标方法的执行在方法调用前记录开始时间在方法返回后计算耗时。public class TimingInterceptor { RuntimeType public static Object intercept(Origin Method method, AllArguments Object[] args, SuperCall Callable? callable) throws Exception { long start System.currentTimeMillis(); String traceId TraceContext.get(); try { return callable.call(); } finally { long cost System.currentTimeMillis() - start; if (cost 200) { SlowLog log new SlowLog(); log.setTraceId(traceId); log.setMethod(method.getDeclaringClass().getName() . method.getName()); log.setCost(cost); log.setParams(summarizeArgs(args)); System.out.println(JsonUtil.toJson(log)); } } } }有几个细节值得单独说。第一阈值200ms是一个经验值你可以根据被测系统的实际情况调整。如果业务本身平均响应就是300ms那阈值可以调到500ms避免正常方法全部被打出来。如果是对性能要求极高的接口阈值甚至可以调到50ms。核心原则是“只记录异常值不要记录全部”。第二summarizeArgs一定要做参数摘要。真实业务里参数可能是一个巨大的对象直接打印会刷屏还可能出现toString抛异常的情况。我通常会截取前200个字符或者把List/Map等集合只输出size保证日志可读。第三这里用System.out.println只是做演示。真实落地时建议用Logback或Log4j2输出到独立文件方便后续用grep和jq分析。3.4 请求ID的串联为了把Controller层的日志和Service层、SQL层的日志关联起来必须有一个贯穿整个请求的ID。在Spring Boot项目中我一般用一个Filter来实现。Component public class TraceFilter implements Filter { Override public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException { String traceId UUID.randomUUID().toString().replace(-, ); TraceContext.set(traceId); try { chain.doFilter(request, response); } finally { TraceContext.clear(); } } }TraceContext就是一个简单的ThreadLocal封装public class TraceContext { private static final ThreadLocalString HOLDER new ThreadLocal(); public static void set(String traceId) { HOLDER.set(traceId); } public static String get() { return HOLDER.get(); } public static void clear() { HOLDER.remove(); } }使用ThreadLocal要注意一个坑如果业务代码里开了异步线程或者用了线程池ThreadLocal里的值不会自动传递到子线程。这个问题我在后面“常见问题”部分再展开讲这里先记住结论。3.5 把SQL执行耗时也串进来对Controller和Service插桩只能看到方法级别的耗时但慢查询的核心还在于SQL。我们还需要在数据库访问层插一层探针。如果项目用的是MyBatis最直接的方式是写一个MyBatis的Interceptor拦截Executor的query和update方法。Intercepts({ Signature(type Executor.class, method update, args {MappedStatement.class, Object.class}), Signature(type Executor.class, method query, args {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class}) }) public class SqlCostInterceptor implements Interceptor { Override public Object intercept(Invocation invocation) throws Throwable { MappedStatement ms (MappedStatement) invocation.getArgs()[0]; String sqlId ms.getId(); Object parameter invocation.getArgs()[1]; Object result; long start System.currentTimeMillis(); try { result invocation.proceed(); } finally { long cost System.currentTimeMillis() - start; if (cost 100) { SlowLog log new SlowLog(); log.setTraceId(TraceContext.get()); log.setMethod(SQL: sqlId); log.setCost(cost); log.setParams(summarizeParams(parameter)); System.out.println(JsonUtil.toJson(log)); } } return result; } }然后在MyBatis配置里注册这个InterceptorConfiguration public class MyBatisConfig { Bean public SqlCostInterceptor sqlCostInterceptor() { return new SqlCostInterceptor(); } }如果你的项目用的是Spring Data JPA、JdbcTemplate或者原生JDBC原理也是一样的只不过切点从MyBatis的Executor换成了JDBC层的PreparedStatement。拦截JDBC层有一个额外的好处对上层框架完全无感不管底层是MyBatis还是Hibernate最终都要走JDBC所以插桩覆盖面最广。但坏处是要处理的JBDC接口方法比较多一上来就先从MyBatis切点入手已经能覆盖绝大多数测试场景。3.6 日志怎么落盘和查看我把插桩日志统一输出到一个独立的日志文件比如slow-query-trace.log每行一个JSON对象。样例日志大概是长这样的{traceId:a3f9e8c2d1b24a6fb4d34a0c4e5f6a7b,type:CONTROLLER,method:com.demo.controller.OrderController.queryList,cost:3251,params:page1,size20} {traceId:a3f9e8c2d1b24a6fb4d34a0c4e5f6a7b,type:SERVICE,method:com.demo.service.OrderServiceImpl.queryPage,cost:3210,params:userId1001} {traceId:a3f9e8c2d1b24a6fb4d34a0c4e5f6a7b,type:SQL,method:SQL:com.demo.mapper.OrderMapper.selectOrderPage,cost:2890,params:userId1001,offset0,limit20}看到没同一个traceId下接口、方法、SQL的耗时一目了然。用纯命令行工具就能做初步分析# 找出所有超过500ms的SQL grep type:SQL slow-query-trace.log | jq select(.cost 500) # 按方法聚合输出Top慢方法 grep type:SERVICE slow-query-trace.log | jq -r [.method,.cost] | tsv | awk -F\t {sum[$1]$2; cnt[$1]} END{for (m in sum) print sum[m], cnt[m], m} | sort -nr | head -20如果你的测试环境有ELK或者Loki这类日志系统直接把插桩日志发过去查询和聚合会更爽。但对于大多数测试环境一个独立日志文件加jq命令已经足够用。4. 慢查询根因定位与自动化测试实战4.1 从日志里揪出“真凶”一个N1查询的案例这里分享一个很典型的案例。有一次测试环境出现一个接口偶发变慢现象是订单列表接口有时候1秒内返回有时候超过3秒。数据库慢查询日志里偶发出现几条单条执行几百毫秒的SQL但看起来都不至于让接口慢那么多。挂上插桩Agent之后问题一下就清楚了。同一个traceId下出现了几十条SQL日志全部是select * from order_item where order_id ?这种单条执行时间都很短也就3到10毫秒但数量有45条累积耗时接近2.8秒。再看SERVICE层的日志OrderServiceImpl.queryPage这个方法刚好也是2.8秒左右。这就是典型的N1查询问题先查订单主表拿到一批订单再循环每条订单去查明细一条条拼出来。如果只看数据库慢查询日志这些SQL单条都不慢根本不会被记录但插桩日志按traceId一聚整个循环的累积耗时就暴露出来了。这个案例给我最大的感触是慢查询测试不能只盯着“单条慢SQL”还要关注“大量短SQL的累积效应”。而插桩日志正好能把“大量短SQL”按照同一个请求串联起来这是数据库慢日志做不到的。4.2 把插桩采集接入自动化测试流程慢查询测试最有价值的场景其实是和自动化测试结合起来。做法很简单测试服务启动的时候挂上Agent自动化测试用例照常跑。跑完一轮回归之后直接分析插桩日志把超过阈值的方法和SQL提取出来作为当轮测试报告的一部分。这么做有一个很大的好处你不需要专门去构造慢查询用例。很多慢查询问题其实是和特定数据量、特定参数组合绑定在一起的手工造数据往往造不全但自动化回归会跑各种各样的场景只要触发过一次插桩日志就会留下痕迹。我现在的做法是给每个环境固定的Agent日志目录自动化测试有一套清理和读取日志的逻辑。每次回归结束后脚本自动执行grep type:SQL slow-query-trace.log | jq select(.cost 500) | wc -l返回值超过预设阈值测试报告直接标红相关traceId一并附上开发人员拿着traceId去日志平台拉全链路日志定位效率高很多。4.3 慢查询测试报告怎么做才不挨骂很多测试同学做性能报告缺乏说服力是因为只有“现象”没有“根因”。比如报告写“订单列表接口平均耗时3秒”开发看完还是一头雾水到底慢在数据库还是慢在代码用插桩日志做报告可以做到每一条慢查询都能追溯到具体的方法和SQL。我一般把报告分成三个层级第一层Top慢接口。给出接口路径、平均耗时、最大耗时、慢请求次数。第二层Top慢方法。给出类方法名、平均耗时、慢调用次数并附带traceId列表。第三层Top慢SQL。给出sqlId、执行耗时、调用次数、参数示例。最后再做一个简单的接口耗时和SQL耗时对比表接口路径接口耗时(ms)内部最大SQL耗时(ms)SQL调用数量初步结论/api/order/list3251289045N1查询SQL累计耗时占比高/api/user/login1020303SQL不慢疑似外部调用或锁等待这个表格虽然简单但信息量非常大。开发一眼就能看出来第一个问题的方向是SQL调用次数第二个问题的方向是外部调用或者锁不用再从头猜起。另外报告里一定要附上traceId。开发拿到traceId去日志平台一看所有日志都在同一条链路里什么问题都藏不住。只要报告做到这个程度开发对你的认可度会上升一个层级。5. 常见问题与避坑清单5.1 插桩本身对性能有影响吗这个问题每次都会被问。插桩代码本身的开销非常低就是记一下时间戳、比较一下阈值、偶尔打一条日志对测试环境来说完全可以忽略。真正影响性能的是日志输出和序列化如果每次请求都打印完整参数日志量会迅速爆掉。我见过有人把插桩阈值设成0结果所有方法都记录日志文件几分钟就把磁盘写满。应对方式有两个一是设置合理阈值默认200ms以上才记录二是把日志输出改成异步不要阻塞业务线程。生产环境要插桩的话建议加一个“抽样开关”比如只记录10%的请求或者只记录指定接口的请求避免日志量不可控。5.2 异步线程导致请求ID丢失怎么办这是插桩方案里最典型的一个坑。业务代码中经常用异步线程池或者Async去执行任务此时ThreadLocal里的traceId不会自动传到子线程导致子线程里执行的SQL方法日志traceId为空无法和父线程关联起来。最简单的临时方案是在日志里用线程名做关联。但这个方法不稳定因为同一个线程可能会复用于多个请求。更靠谱的做法是在线程池中传递上下文比如包装任务对象public class TraceAwareRunnable implements Runnable { private final Runnable delegate; private final String traceId; public TraceAwareRunnable(Runnable delegate) { this.delegate delegate; this.traceId TraceContext.get(); } Override public void run() { TraceContext.set(traceId); try { delegate.run(); } finally { TraceContext.clear(); } } }然后用这个包装类去提交异步任务traceId就能在子线程里延续下去。Spring的ThreadPoolTaskExecutor可以设置TaskDecorator实现同样效果。5.3 为什么插桩日志里有些慢方法没有对应SQL这个现象很常见也恰恰是插桩方案帮你缩小范围的价值所在。如果某个方法耗时大但对应的SQL日志里没有记录说明慢的原因不在数据库而可能在Redis、外部HTTP调用、分布式锁等待、或者GC停顿。这时候你虽然还没定位到最终根因但至少可以明确告诉开发数据库在这段耗时里没有参与问题出在业务代码的其他环节。我在实际项目中把插桩范围逐步扩大到了Redis客户端和HTTP客户端让每个IO节点也输出耗时日志。这样定位慢查询的时候链路完整度更高排查速度会再快一个档次。5.4 常见问题速查表问题现象可能原因解决办法日志中方法耗时很大但没有SQL记录SQL未执行或SQL阈值设置太高调低SQL阈值检查方法内是否在做Redis/HTTP调用traceId为空请求没走过滤器或异步线程丢了上下文检查过滤器拦截路径线程池做上下文传递Agent没有生效类名匹配规则不对或类先于Agent加载确认匹配规则改用-javaagent方式启动并观察启动日志日志量爆炸阈值太低或接口流量过大调高阈值日志异步输出增加抽样开关慢SQL条数和数据库慢日志对不上应用层阈值和数据库阈值不同或数据库有采样以应用层数据为准慢日志做交叉验证测试环境做的慢查询插桩和数据库的slow log并不是二选一建议两个都要用。插桩负责定位应用层链路slow log负责核对真实的SQL执行计划和索引情况两者互相补充才能把慢查询的来龙去脉摸清楚。这套思路我已经在项目里跑了挺长时间最开始两周还会被各种漏抓慢SQL的细节坑到把插桩范围逐步补齐之后排查慢查询的效率提升非常明显。最后再分享一个很实用的小技巧把Agent打包好之后在服务启动脚本里用一个环境变量控制开关比如JAVA_OPTS里带上-javaagent:slowquery-agent.jar不需要的时候直接去掉完全不影响业务代码。另外在测试回归流程里先跑一遍自动化用例再去看插桩日志比手工点十次页面都有效这个组合是我目前用下来最省力的慢查询测试方法。
