开发者日记

外观

慢接口从 3.2s 到 180ms：SkyWalking 调用链与 SQL 耗时联合定位实录 ​

问题背景：接口慢，不一定是 SQL 真的慢 ​

一次线上订单详情接口 /api/orders/{id} 在高峰期 P95 从 200ms 上升到 3.2s，应用 CPU 并不高，数据库实例负载也没有明显打满。最初团队怀疑是某条索引失效，但直接在数据库里执行 SQL，耗时只有 30ms。

这类问题的关键在于：用户感受到的是一次完整请求耗时，而 SQL 执行时间只是其中一段。一次慢接口可能由以下部分叠加而成：

  • 应用线程排队、锁等待；
  • 数据库连接池获取连接等待；
  • SQL 网络往返、执行、结果集映射；
  • Redis、RPC、HTTP 等下游调用；
  • 同一事务内多条 SQL 的累计耗时；
  • Trace 采样遗漏导致看到的链路不完整。

SkyWalking 的价值不只是展示“哪个接口慢”，而是把入口请求、方法 Span、数据库 Span、中间件 Span 串成调用链。配合数据库侧的慢 SQL 日志和执行计划，才能判断问题到底发生在 SQL 本身、连接池，还是下游依赖。

方案对比：为什么要联合分析 ​

常见定位方式有三类：

方案能看到什么主要局限适用场景
应用日志方法开始结束、业务参数跨线程、跨服务上下文容易断单点问题复现
数据库慢日志SQL 执行耗时、扫描行数看不到连接等待和调用来源确认 SQL 是否真实变慢
SkyWalking 调用链请求全路径、Span 耗时、组件信息采样、埋点不完整会影响判断分布式慢接口定位

只看慢 SQL 日志，会把“拿不到连接”误判成“数据库执行慢”；只看 SkyWalking，又可能忽略数据库内部的执行计划。正确做法是：先用 Trace 找耗时分布，再用 SQL 指纹、执行计划和连接池指标验证根因。

下面这张图描述了联合分析的定位路径：

入口接口告警P95 3.2sSkyWalking Trace查看 Span 耗时数据库 SpanSQL 与连接信息下游 SpanRPC/Redis/HTTP慢日志与执行计划验证根因优化索引、事务、连接池后回归验证

实操步骤：搭建可被 SkyWalking 追踪的 Java 接口 ​

示例使用 Spring Boot 3、MyBatis、MySQL 和 HikariCP。重点不是业务复杂度，而是保证一次请求中的 HTTP、SQL、连接池等待都能在 Trace 中被观察到。

1. 添加接口与查询逻辑 ​

java
@RestController
@RequiredArgsConstructor
public class OrderController {

    private final OrderService orderService;

    @GetMapping("/api/orders/{id}")
    public OrderDetailResponse getOrder(@PathVariable Long id) {
        return orderService.getDetail(id);
    }
}

@Service
@RequiredArgsConstructor
public class OrderService {

    private final OrderMapper orderMapper;
    private final OrderItemMapper itemMapper;

    @Transactional(readOnly = true)
    public OrderDetailResponse getDetail(Long id) {
        // 主订单查询
        Order order = orderMapper.selectById(id);
        if (order == null) {
            throw new ResponseStatusException(HttpStatus.NOT_FOUND, "订单不存在");
        }

        // 明细查询：高峰期该 SQL 出现全表扫描
        List<OrderItem> items = itemMapper.selectByOrderId(id);
        return OrderDetailResponse.of(order, items);
    }
}

对应 MyBatis Mapper：

java
@Mapper
public interface OrderItemMapper {

    @Select("""
        SELECT id, order_id, sku_id, quantity, price
        FROM order_item
        WHERE order_id = #{orderId}
        ORDER BY id ASC
        """)
    List<OrderItem> selectByOrderId(Long orderId);
}

2. 配置数据库连接池 ​

yaml
spring:
  datasource:
    url: jdbc:mysql://127.0.0.1:3306/demo?useSSL=false&serverTimezone=Asia/Shanghai
    username: root
    password: root
    hikari:
      maximum-pool-size: 20
      minimum-idle: 5
      connection-timeout: 1000
      max-lifetime: 1800000
      pool-name: DemoHikariPool

这里将 connection-timeout 设置为 1000ms，是为了让连接池耗尽时快速失败，而不是让请求长时间挂起。注意，连接池过小会造成等待，盲目调大又会把压力传导给 MySQL，需要结合 SkyWalking 与数据库连接数一起判断。

3. 挂载 SkyWalking Java Agent ​

本地启动时增加 JVM 参数：

bash
java -javaagent:/opt/skywalking-agent/skywalking-agent.jar \
  -Dskywalking.agent.service_name=order-service \
  -Dskywalking.collector.backend_service=127.0.0.1:11800 \
  -jar order-demo.jar

访问几次慢接口后，在 SkyWalking UI 的 Trace 页面按 /api/orders 过滤，重点看三个字段：

  • Duration：整个请求耗时；
  • Component：当前 Span 属于 Spring MVC、MySQL/JDBC 还是 HTTP 客户端；
  • Tags：SQL 语句、连接地址、状态码、异常信息。

如果数据库 Span 只有 30ms，但父 Span 有 3s，不要立刻认定是 SQL 慢。需要继续展开相邻 Span，观察是否存在连接池等待、锁竞争或者其他下游调用。

SQL 耗时联合分析：从 Trace 到执行计划 ​

本次案例中，Trace 显示接口总耗时 3.2s，其中 SELECT ... FROM order_item WHERE order_id = ? 的数据库 Span 在高峰期达到 1.8s，而同一 SQL 在低峰期手动执行只需 30ms。继续查看 MySQL 慢日志：

sql
SELECT id, order_id, sku_id, quantity, price
FROM order_item
WHERE order_id = 123456
ORDER BY id ASC;

慢日志关键字段如下：

text
Query_time: 1.812483  Lock_time: 0.000120 Rows_examined: 2849201 Rows_sent: 4

Rows_examined 远大于 Rows_sent，说明扫描了大量无效行。执行 EXPLAIN：

sql
EXPLAIN SELECT id, order_id, sku_id, quantity, price
FROM order_item
WHERE order_id = 123456
ORDER BY id ASC;

结果中 type=ALL，key=NULL，rows 接近 300 万，确认是缺少合适索引。添加联合索引：

sql
ALTER TABLE order_item
ADD INDEX idx_order_id_id (order_id, id);

再次查看执行计划，type 变为 ref，key 为 idx_order_id_id，扫描行数下降到个位数。

但优化并没有结束。Trace 中还发现部分请求在 SQL Span 之前存在约 800ms 的空洞。结合 HikariCP 指标 pendingThreads 上升、activeConnections 长期等于最大连接数，判断是连接池耗尽。进一步排查发现，部分代码在事务内调用外部 HTTP 接口，导致数据库连接被长时间占用。

修复原则是：事务只包数据库操作，远程调用移到事务外部。

java
@Service
@RequiredArgsConstructor
public class OrderQueryService {

    private final OrderService orderService;
    private final InventoryClient inventoryClient;

    public OrderDetailResponse getDetail(Long id) {
        // 先执行远程调用，不占用数据库连接
        InventoryDTO inventory = inventoryClient.query(id);

        // 短事务读取数据库
        OrderDetailResponse response = orderService.getDetail(id);
        response.setInventory(inventory);
        return response;
    }
}

完成索引修复和事务范围收敛后，接口 P95 从 3.2s 降到 180ms，数据库 Span 稳定在 30ms 左右，连接池等待基本消失。

避坑总结：慢接口定位中的高频误判 ​

1. 只看平均耗时，忽略 P95 和 Trace 样本 ​

错误现象：监控图平均耗时正常，但用户频繁反馈超时。平均值会被大量低峰请求稀释。

修正方法：同时看 P95、P99、错误率和吞吐量，并在 SkyWalking 中筛选高耗时 Trace。慢问题通常只在特定参数、特定时间段或特定下游实例上出现。

2. 把连接池等待误判成 SQL 执行慢 ​

错误现象：接口 Span 很长，但数据库慢日志里的 Query_time 很短，开发同学直接去优化一条并不慢的 SQL。

修正方法：对比 Trace 中 JDBC Span 开始前是否有明显空洞，同时观察 HikariCP 的 activeConnections、pendingThreads、connectionAcquireTime。如果等待高，应优先缩短事务、检查慢查询占用连接，而不是盲目增大连接池。

3. SQL 指纹不一致，导致 Trace 和慢日志对不上 ​

错误现象：SkyWalking 中看到的是 WHERE order_id = ?，慢日志里是完整参数值，排查时误以为不是同一条 SQL。

修正方法：按 SQL 模板归一化匹配，去掉具体参数，提取表名、字段、条件和排序方式。必要时在应用日志中打印 traceId，再用数据库侧审计日志或代理层日志做关联。

4. 采样率过低，关键慢请求没有被记录 ​

错误现象：问题发生时用户报错，但 SkyWalking 查不到对应 Trace，或者 Trace 缺少下游 Span。

修正方法：生产环境不要在核心链路上使用过低采样率。可以采用默认采样加错误、慢请求强制采样的策略。同时确认 Java Agent 版本与中间件插件版本兼容，避免 JDBC 或 HTTP 客户端插件未生效。

5. 只优化单条 SQL，不看事务内累计耗时 ​

错误现象：每条 SQL 都不慢，但一个接口在事务中循环执行几十次查询，总耗时仍然很高。

修正方法：在 Trace 中统计同一事务下所有数据库 Span 的总和。能批量查询就不要循环查库，能延迟加载的字段不要在主链路强制加载，并避免事务内包含 RPC、消息发送等不可控操作。

慢接口定位不是看到红色 Span 就结束，而是要把调用链时间轴、SQL 执行计划、连接池指标和业务并发模型放在一起验证。SkyWalking 负责回答“时间花在哪一段”，数据库侧证据负责回答“为什么这一段慢”。两者联合分析，才能把偶发、复杂的性能问题从猜测变成可复现、可验证的优化闭环。

免责声明

本工具与文章内容仅用于学习测试场景，优化建议仅供参考，请勿直接用于生产环境，由此产生的风险自行承担。

本文来自开发者日记（devdiary.cn）· 记录开发者实战笔记与免费在线工具箱

免责声明

本工具与文章内容仅用于学习测试场景，优化建议仅供参考，请勿直接用于生产环境，由此产生的风险自行承担。