1. 先聊清楚测试里的慢查询为什么难搞我做了几年的服务端测试和性能调优有一个场景几乎每次版本迭代都会遇到接口响应时间突然从 80ms 飙到 800ms线上监控一查发现是数据库慢查询但这个问题在测试环境里死活复现不出来。等到上线后用户开始投诉DBA 那边调出慢查询日志才发现是一条走了全表扫描的 SQL只在特定数据量、特定索引失效的情况下才会变慢。这个问题的本质在于慢查询不是一个“有或无”的问题而是一个“触发条件”的问题。触发条件可能包括数据量级、缓存命中率、并发压力、参数嗅探、索引选择甚至是一次不恰当的统计信息更新。测试环境里数据量小、并发低、缓存新鲜很多慢查询根本不会冒头。想解决这个问题不能只靠“多写几条 SQL 然后 explain”而是得有一套能主动捕获慢查询、并把它和具体业务场景、具体代码调用链关联起来的机制。插桩技术就是用来干这个的。插桩这个词听起来有点底层好像只有做 APM、做编译器的人才会碰。但放到测试场景里它的思路非常简单在你关心的关键路径上主动埋下探针采集执行数据把这些数据汇总起来形成报表用于定位问题。用在慢查询测试上就是两件事第一找到哪条 SQL 慢第二搞清楚这条 SQL 是在哪个接口、哪个业务操作、哪个数据量条件下变慢的。这套思路适合谁适合所有被“测试环境一切正常上线就出问题”折磨过的测试工程师、后端开发、性能测试同学。不需要你有多深的字节码功底也不需要动线上代码只要你手头有一个可运行的测试环境再配合一点简单的埋点手段就能把慢查询问题从“靠运气复现”变成“靠机制发现”。2. 核心思路拆解给程序装探头把慢查询“看”清楚2.1 插桩技术的基本原理它到底在做什么插桩的本质是在程序运行路径中插入一段额外的观测代码就像在一条管道上装流量计。这段观测代码本身不影响业务逻辑只是记录“经过这里时的状态”耗时多少、入参是什么、走了哪条分支、调用了什么下游。放到慢查询测试里我们需要观测的点有三个SQL 执行入口也就是 DAO 层或者 ORM 框架执行 SQL 的地方业务方法入口也就是 Service 层或 Controller 层处理请求的地方数据访问上下文也就是当前请求携带的用户、场景、参数、数据量等信息如果你手动在代码里加日志这当然也是一种插桩但问题是太折腾而且容易漏。更推荐的做法是用现成的中间件或框架能力来做比如 Java 里的 MyBatis Interceptor、Spring AOPMySQL 自带的慢查询日志或者像 SkyWalking 这类 APM 工具里内置的 SQL 采集能力。它们本质上都是“插桩”只是位置和粒度不同。2.2 为什么不能只靠数据库慢查询日志很多团队的第一反应是打开 MySQL 的 slow_query_log 不就行了吗确实这能拿到最直接的 SQL 文本和执行耗时但光有它远远不够。我举个例子。假设慢查询日志里记录了这样一条SELECT * FROM order_detail WHERE user_id 12345 AND status 1 ORDER BY create_time DESC LIMIT 20;执行耗时 2.3 秒。你看到这条 SQL能立刻说出是哪个页面、哪个操作导致的吗大概率不能。你还需要去代码里全局搜这条 SQL然后反查是哪个 Mapper 方法、哪个 Service 在调用再结合调用栈去推断业务场景。如果这个 Mapper 方法被十几个接口复用了你就得一个个排除。慢查询日志只回答了“哪条 SQL 慢”但没回答“在什么业务场景下慢”。而后一个问题恰恰是测试同学复现问题、定位根因最需要的信息。所以慢查询日志是底座但光有底座不够必须往上叠加应用层的插桩数据把 SQL、接口、参数、场景串联起来。2.3 统计口径的设计比工具更重要的思路工具选型是后话思路里的核心其实是统计口径。你准备拿什么指标来判断“慢”多长时间算慢这个口径设计不好后面全白搭。先说结论我的建议是至少从两个维度看绝对阈值单条 SQL 执行时间超过某个值比如 500ms直接判为慢相对基线同一条 SQL 在正常情况下的平均耗时是 30ms某次测试里变成 300ms虽然绝对值没过阈值但已经涨了 10 倍这种也必须抓只做绝对阈值会漏掉那些“本来很快、突然劣化”的 SQL只做相对基线会有很多误报因为测试环境的数据量抖动本来就会带来波动。两个维度一起看才能既抓得住大问题也不放过小劣化。这套思路想清楚了你再去选工具、写脚本都会顺手很多。因为你不是在盲目收集数据而是带着明确的观测目标去做插桩。3. 实操落地从零到一搭一套慢查询插桩方案3.1 我的推荐组合MySQL 慢查询日志 应用层 AOP 数据汇聚下面这套方案不是唯一解但很适合测试团队快速落地我用的也是这套组合第一层开启 MySQL 慢查询日志设置一个相对敏感的阈值测试环境可以设 200ms第二层在应用代码里用 AOP 拦截 Service 层方法记录业务方法耗时用 MyBatis Interceptor 或 Hibernate 拦截 SQL 执行记录 SQL 耗时第三层把两层日志通过 traceId 关联起来汇聚成一张“接口-方法-SQL”的明细表这三层分别回答不同的问题MySQL 慢查询日志回答“数据库视角哪条 SQL 慢”应用层插桩回答“业务视角哪个操作慢”traceId 关联回答“慢 SQL 是由哪个请求触发的”。3.2 第一步开启慢查询日志并解决“日志轮转”问题MySQL 侧的操作不复杂但要小心几个坑。先看基础配置-- 查看当前配置 SHOW VARIABLES LIKE slow_query_log%; SHOW VARIABLES LIKE long_query_time; SHOW VARIABLES LIKE log_queries_not_using_indexes; -- 动态开启重启失效 SET GLOBAL slow_query_log ON; SET GLOBAL long_query_time 0.2; SET GLOBAL log_queries_not_using_indexes ON;long_query_time的单位是秒测试环境我建议设成 0.2也就是 200ms这样能捕捉到大多数潜在问题。线上一般设 1 秒但测试环境为了“多看问题”阈值可以激进一点。log_queries_not_using_indexes这个开关建议一并打开它会把没走索引的查询也记录下来即使执行时间没超过阈值。这个配置对测试特别有用因为它能提前暴露索引失效的问题。需要特别注意日志轮转。默认情况下 MySQL 会不断往同一个慢查询日志文件里写时间长了文件会变得巨大甚至影响磁盘空间。建议在测试服务器上用 logrotate 做日志切割# /etc/logrotate.d/mysql-slow /var/log/mysql/mysql-slow.log { daily rotate 7 compress missingok postrotate mysqladmin flush-logs endscript }3.3 第二步应用层埋点把 SQL 和业务场景“绑”起来只有数据库日志你只能看到 SQL 文本和耗时。要想知道这条 SQL 来自哪个接口、哪个用户、哪次操作就得在应用层做文章。如果你的项目是 Java 技术栈MyBatis 的 Interceptor 是最省事的埋点位置。下面是一个简化版的拦截器它的作用是在 SQL 执行前后记录耗时并捕获当前请求的 traceIdIntercepts({ 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 { private static final ThreadLocalString TRACE_ID_HOLDER new ThreadLocal(); public static void setTraceId(String traceId) { TRACE_ID_HOLDER.set(traceId); } Override public Object intercept(Invocation invocation) throws Throwable { long start System.currentTimeMillis(); try { return invocation.proceed(); } finally { long cost System.currentTimeMillis() - start; MappedStatement ms (MappedStatement) invocation.getArgs()[0]; String sqlId ms.getId(); String traceId TRACE_ID_HOLDER.get(); if (cost 50) { System.out.println([SLOW-SQL] traceId traceId , sqlId sqlId , cost cost ms); } TRACE_ID_HOLDER.remove(); } } Override public Object plugin(Object target) { return Plugin.wrap(target, this); } }然后在 Controller 入口处通过拦截器或过滤器生成 traceId并塞到 ThreadLocal 里Component public class TraceIdFilter implements Filter { Override public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException { String traceId UUID.randomUUID().toString().replace(-, ); SqlCostInterceptor.setTraceId(traceId); try { chain.doFilter(request, response); } finally { // 请求结束清理 ThreadLocal避免线程池复用导致串号 } } }这样每次请求都会生成一个唯一的 traceId这个 traceId 会贯穿到 SQL 执行的埋点日志里。拿到一条慢 SQL 的日志后用 traceId 去查应用日志就能定位到完整的调用链。这里有个非常关键的经验一定要在 finally 里清理 ThreadLocal。如果服务用了线程池线程是复用的不清理的话下一个请求会读到上一个请求的 traceId排查问题的时候会被带偏。3.4 第三步设定采集维度把数据变成可分析报表日志打出来了还不够要把数据变成可分析的形式。我最常用的做法是把埋点日志输出到独立的文件然后用 Logstash 或者简单的 Python 脚本按分钟聚合最终落到一个 test_report 表里包含以下字段trace_id请求唯一标识interface_name接口名/PATHmethod_nameService 方法名或 Mapper 方法 IDsql_text慢 SQL 文本sql_cost_msSQL 执行耗时request_time请求时间extra_params可选的扩展字段比如 userId、订单号等这张表建好之后你就可以用 SQL 做各种分析哪个接口产生的慢 SQL 最多、哪条 SQL 平均耗时最高、哪个时间窗口慢查询最集中、SQL 耗时和接口耗时之间的差距有多大。这个过程其实就是把“零散的日志”变成“结构化的测试结论”。我建表之后最常用的几条查询长这样-- 按接口维度统计慢 SQL 数量 SELECT interface_name, COUNT(*) AS slow_cnt, ROUND(AVG(sql_cost_ms), 2) AS avg_cost FROM slow_sql_report WHERE report_date CURRENT_DATE GROUP BY interface_name ORDER BY slow_cnt DESC; -- 查询同一 traceId 下所有 SQL还原一次请求的完整 SQL 执行序列 SELECT sql_text, sql_cost_ms, method_name FROM slow_sql_report WHERE trace_id 某个具体的traceId ORDER BY id;到这里一套能落地的慢查询插桩方案就成形了。从数据库层到应用层再到分析层每一层都在回答不同的问题。4. 我踩过的坑这些细节不处理方案等于白搭4.1 坑一慢查询日志“时有时无”其实是阈值和采样问题有段时间我发现测试环境的慢查询日志特别稀疏明明接口已经明显变慢了日志里却只有几条记录。排查之后发现是两个原因叠加一是long_query_time设得偏大二是测试环境的 SQL 大多走了缓存真正打到磁盘的查询不多。解决办法是把阈值调低并清理缓存。注意MySQL 的查询缓存即使命中也仍然会去解析 SQL但执行时间会显著下降。为了让慢查询能稳定复现建议在测试方案里加上“清缓存”前置步骤RESET QUERY CACHE;或者干脆在测试环境关闭查询缓存避免缓存命中掩盖真实的 SQL 性能问题。4.2 坑二traceId 在异步线程里丢失一个典型的场景接口在主线程里生成了 traceId但某条 SQL 是在异步线程池里执行的比如一个任务回调、一个 MQ 消费逻辑。由于 ThreadLocal 是线程隔离的异步线程根本读不到主线程塞进去的 traceId导致慢 SQL 日志里 traceId 为空无法关联业务场景。我的处理方式是在提交异步任务时手动传递 traceIdExecutorService executor new ThreadPoolExecutor(...); String traceId SqlCostInterceptor.getTraceId(); executor.submit(() - { SqlCostInterceptor.setTraceId(traceId); try { // 异步任务真实逻辑 } finally { SqlCostInterceptor.clear(); } });类似的坑还出现在 Redis 回调、MQ 监听器、定时任务里。只要你发现日志里有 SQL 慢记录但 traceId 是空的不用怀疑基本都是这类问题。4.3 坑三埋点影响性能导致测试数据失真插桩本身是有开销的。MyBatis Interceptor 里的反射调用、日志输出、traceId 生成都会增加额外耗时。如果埋点写得太重比如每个 SQL 都打印完整参数、每个方法都记录堆栈那最终的耗时数据里掺杂了太多插桩自身的时间反而不准。我的建议是分级采样所有 SQL 都记录耗时但只在耗时超过阈值时才输出详情接口层埋点只记方法名和耗时不记参数体日志输出用异步方式或者直接写到独立文件避免和业务日志混在一起造成 IO 抢占另外埋点上线后做一个“空跑对比”在没有慢查询的场景里跑一遍接口看插桩带来的额外耗时大概是多少。如果额外耗时稳定在 10ms 以内对测试结论的影响就很有限如果超过 50ms就要精简埋点逻辑了。4.4 坑四慢查询日志只记录执行结束后的结果中间态丢失MySQL 慢查询日志是在 SQL 执行完之后才记录的它只能告诉你“这条 SQL 花了多久”但没法告诉你“执行过程中走了哪个索引、扫描了多少行、临时表用了多少”。这些中间态对定位根因极其重要。所以我在捕获到慢 SQL 之后还有一步固定动作把 SQL 文本拿去做 EXPLAIN ANALYZE。MySQL 8.0 以后支持 EXPLAIN ANALYZE它会真实执行 SQL 并给出每一步的耗时和行数比传统 EXPLAIN 准确得多EXPLAIN ANALYZE SELECT * FROM order_detail WHERE user_id 12345 AND status 1 ORDER BY create_time DESC LIMIT 20;执行结果里能看到是不是全表扫描、 sort_buffer 用了多少、索引扫描行数和返回行数的比例。这一步能直接定位到“为什么慢”是缺索引、索引失效、排序太重还是数据倾斜。5. 一次完整的实战复盘用这套思路定位一个真实慢查询5.1 现象某次版本测试中我的测试脚本报告“订单列表接口”P95 响应时间从 180ms 涨到了 860ms但功能表现完全正常没有任何报错。按照之前的经验先把慢查询日志调出来看果然发现一条 SQL 多次出现在慢查询列表里SELECT * FROM order_info WHERE user_id 12345 AND pay_status IN (1, 2) AND deleted 0 ORDER BY id DESC LIMIT 20;执行耗时在 1.2 秒到 2.1 秒之间跳动。但奇怪的是这条 SQL 在之前的测试里从来没慢过索引也是有的。5.2 插桩数据怎么帮我缩小范围靠数据库日志我只能看到这一条 SQL但应用层埋点给了我额外信息慢 SQL 集中出现在 user_id 尾号为奇数的那批账号上。结合 traceId 反查后发现这些请求都来自同一个模拟用户批量下单的测试脚本而这个脚本在下单前会构造大量 order_info 数据。也就是说这不是 SQL 本身写坏了而是数据分布发生了变化。某些 user_id 下的订单数据量特别大单用户的数据行数已经超过 50 万LIMIT 20 的查询在这批数据上走索引也可能扫出大量行。5.3 用 EXPLAIN ANALYZE 锁定根因对这条 SQL 执行 EXPLAIN ANALYZE 之后关键信息出来了虽然走了 idx_user_id 索引但由于需要回表过滤 pay_status、deleted再加上排序优化器计算出的成本反而更倾向于全表扫描。数据量小的账号没问题是因为优化器认为走索引成本更低数据量大的账号则触发了错误的选择。根因找到了复合索引idx_user_id (user_id)对单字段查询有效但无法覆盖 WHERE 中的 pay_status 和 deleted 两个过滤条件导致大量回表。5.4 修复与验证修复方式是建立覆盖索引ALTER TABLE order_info ADD INDEX idx_user_status_deleted (user_id, pay_status, deleted, id);重新跑同一批测试脚本慢 SQL 从列表里消失P95 响应时间稳定回落到了 190ms 左右。这个案例里数据库慢查询日志提供了“线索”应用层插桩提供了“场景”EXPLAIN ANALYZE 提供了“实锤”。三个工具缺一不可而这套流程只有在测试环境提前做好插桩埋点的情况下才能顺畅跑通。如果还是靠“上线后等用户投诉再排查”整个定位周期可能从 1 小时拉长到 1 天。6. 几个关键参数的设置建议直接抄作业很多同学看完上面的思路最容易卡在参数设置上。这里整理一份我在测试环境里常用的配置可以当作初始值再根据具体场景微调。参数项推荐值说明long_query_time0.2200ms测试环境尽量灵敏宁多勿漏log_queries_not_using_indexesON捕获未走索引的查询slow_query_log 文件轮转daily 保留7天避免磁盘空间被日志占满应用层 SQL 埋点输出阈值50ms低于该值的 SQL 不做详情输出traceId 传递范围全链路线程池重点检查异步线程、MQ 消费慢查询分析聚合粒度分钟级和测试脚本执行节奏对齐补充一点long_query_time是否要设置成 0这个要看测试目的。如果是专门做慢查询压测可以临时设为 0捕获所有 SQL如果是回归测试设成 0.2 比较合理不然日志量太大反而淹没了真正需要关注的问题。日志量大不是小事。log_queries_not_using_indexes开启后只要有一条 SQL 没走索引就会持续输出。如果应用里有定时任务每 10 秒跑一次全表扫的统计 SQL那慢查询日志会以肉眼可见的速度膨胀。所以日志轮转和阈值控制一定不能省。7. 这套思路还能怎么扩展慢查询插桩的思路不只是适用于 MySQL本质上它是一个“可观测性”的测试方案。顺着这个思路往下走至少还能扩展出三个方向。第一个方向是扩大到其他数据源。Redis 慢日志、Elasticsearch 慢查询、MongoDB 慢查询、甚至第三方接口的耗时都可以用同样的思路做埋点和关联。只需要把 traceId 继续往下游传递把各个组件的耗时都聚到同一张表里。第二个方向是和自动化测试框架结合。在自动化测试的断言阶段不只校验接口返回结果还额外校验“这个接口产生的慢 SQL 数量是否为 0”。一旦有新增慢 SQL断言直接失败把问题挡在发布之前。我是在测试脚本里把慢 SQL 结果作为性能断言的条件之一这样每次跑回归测试都能自动做一次性能体检。第三个方向是接入告警。测试环境不是只有你在跑可能还有联调、演示、验收在共用。与其人肉盯日志不如写一个定时任务每 5 分钟扫描一次慢 SQL 明细表发现新增记录就推到企业微信或钉钉群。这样不管是谁把环境搞慢了都能第一时间发现。对我来说这套思路最大的价值不在于工具多花哨而在于它让慢查询从“偶发的线上问题”变成了“测试流程里可控的一环”。以前是上线出问题再去查日志现在是在测试阶段就把慢 SQL 揪出来并且能直接告诉开发是哪条 SQL、哪个接口、什么场景下变慢的。省下来的排查时间远比搭这套方案花的时间多。最后再分享一个小技巧如果你们团队暂时没有精力做应用层埋点那至少先把 MySQL 慢查询日志开起来然后写一个每周汇总脚本把 Top 10 慢 SQL 发到群里。这一步不需要任何代码侵入5 分钟就能搞定但已经能帮助你发现相当一部分潜在风险。等你们觉得有必要深挖“哪个场景触发的慢查询”了再补齐应用层的插桩整体效果会立刻上一个台阶。