慢接口排查指南：从 APM 链路追踪到 SQL 执行计划的系统化方法论

网关 → 服务A（业务逻辑） → 服务B（RPC调用） → MySQL → Redis

# 启动命令中挂载 agent
java -javaagent:/path/to/skywalking-agent/skywalking-agent.jar \
     -Dskywalking.agent.service_name=order-service \
     -Dskywalking.collector.backend_service=127.0.0.1:11800 \
     -jar order-service.jar

/order/detail            3200ms  ├──────────────────────────────┤
  ├─ OrderService.detail  180ms  ├──┤
  ├─ UserRPC.getUser      2400ms     ├───────────────────┤
  │    └─ MySQL.select    2350ms        ├────────────────┤  ← 慢在这里
  └─ Redis.get             12ms                            ├┤

/**
 * 基于 AOP 的链路耗时埋点：在关键方法上标注 @TraceSpan 即可记录耗时
 */
@Aspect
@Component
@Slf4j
public class TraceSpanAspect {

    @Around("@annotation(traceSpan)")
    public Object around(ProceedingJoinPoint pjp, TraceSpan traceSpan) throws Throwable {
        String spanName = traceSpan.value();
        String traceId = MDC.get("traceId");  // 由网关过滤器统一塞入
        long start = System.currentTimeMillis();

        try {
            return pjp.proceed();
        } finally {
            long cost = System.currentTimeMillis() - start;
            // 统一格式输出，方便用 ELK 做聚合分析
            log.info("SPAN|{}|{}|{}ms", traceId, spanName, cost);
        }
    }
}

@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface TraceSpan {
    String value();
}

@Service
public class OrderService {

    @TraceSpan("OrderService.detail")
    public OrderDetailVO detail(Long orderId) {
        UserDTO user = userRpcClient.getUser(orderId);   // RPC 调用
        OrderDO order = orderMapper.selectById(orderId); // DB 查询
        return assemble(user, order);
    }
}

@Component
public class TraceIdFilter implements Filter {

    @Override
    public void doFilter(ServletRequest req, ServletResponse res, FilterChain chain)
            throws IOException, ServletException {
        String traceId = UUID.randomUUID().toString().replace("-", "").substring(0, 16);
        MDC.put("traceId", traceId);
        try {
            chain.doFilter(req, res);
        } finally {
            MDC.remove("traceId");  // 防止线程复用导致 traceId 串号
        }
    }
}

@Configuration
public class ThreadPoolMonitorConfig {

    @Bean
    public ThreadPoolExecutor bizThreadPool() {
        ThreadPoolExecutor pool = new ThreadPoolExecutor(
                20, 50, 60L, TimeUnit.SECONDS,
                new LinkedBlockingQueue<>(200),
                new ThreadFactoryBuilder().setNameFormat("biz-pool-%d").build());

        // 定时上报线程池水位，超 80% 打告警日志
        ScheduledExecutorService monitor = Executors.newSingleThreadScheduledExecutor();
        monitor.scheduleAtFixedRate(() -> {
            int active = pool.getActiveCount();
            int max = pool.getMaximumPoolSize();
            int queueSize = pool.getQueue().size();

            log.info("POOL|active={}/{}|queue={}", active, max, queueSize);

            if (active >= max * 0.8) {
                log.warn("POOL_ALERT|线程池水位超 80%: active={}/{}, queue={}",
                         active, max, queueSize);
            }
        }, 0, 10, TimeUnit.SECONDS);

        return pool;
    }
}

@Component
@Slf4j
public class DataSourceMonitor {

    @Autowired
    private DruidDataSource dataSource;

    @Scheduled(fixedRate = 5000)
    public void report() {
        int active = dataSource.getActiveCount();      // 活跃连接
        int pooling = dataSource.getPoolingCount();    // 池中空闲连接
        long waitCount = dataSource.getWaitThreadCount(); // 等待连接的线程数

        log.info("DS|active={}|idle={}|waiting={}", active, pooling, waitCount);

        if (waitCount > 0) {
            // 有线程在等连接，说明连接被长时间占用 —— 大概率有慢 SQL
            log.warn("DS_ALERT|存在等待连接的线程: {}", waitCount);
        }
    }
}

# 启动参数加上 GC 日志
-XX:+PrintGCDetails -XX:+PrintGCDateStamps \
-Xloggc:/var/log/app/gc.log

# 启动并 attach 到目标进程
java -jar arthas-boot.jar

# 实时监控 JVM 面板，重点看 GC 次数和耗时
dashboard

# 追踪某个接口方法耗时，精确到内部每一步
trace com.example.OrderService detail '#cost > 1000'

# 抓取执行中方法的入参和返回值
watch com.example.OrderService detail '{params, returnObj}' -x 2

`---[3250.12ms] com.example.OrderService:detail()
    +---[2.31ms] getOrderFromCache()
    +---[3201.55ms] orderMapper.selectDetail()   ← 98% 耗时在这
    `---[15.20ms] assemble()

EXPLAIN
SELECT o.order_no, o.amount, u.nickname
FROM orders o
LEFT JOIN user u ON o.user_id = u.id
WHERE o.status = 1
  AND o.create_time > '2026-07-01'
ORDER BY o.create_time DESC
LIMIT 20;

-- 执行计划显示：type=ALL, rows=1200000, Extra=Using filesort
SELECT * FROM orders
WHERE DATE(create_time) = '2026-07-20'
ORDER BY amount DESC
LIMIT 10;

-- 1. 去掉函数，改写为范围查询，让 create_time 索引生效
SELECT order_no, amount, status, create_time
FROM orders
WHERE create_time >= '2026-07-20 00:00:00'
  AND create_time <  '2026-07-21 00:00:00'
ORDER BY create_time DESC
LIMIT 10;

-- 2. 建立联合索引，让 WHERE 和 ORDER BY 同时命中
ALTER TABLE orders ADD INDEX idx_ctime (create_time);

-- ① 索引列上使用函数 → 索引失效
WHERE DATE(create_time) = '2026-07-20'

-- ② 隐式类型转换：phone 是 varchar 却传了数字 → 索引失效
WHERE phone = 13800138000

-- ③ 前导模糊查询 → 索引失效
WHERE order_no LIKE '%ABC123'

-- ④ 联合索引不满足最左前缀（索引是 (a,b,c)，跳过了 a）
WHERE b = 1 AND c = 2

-- ⑤ OR 连接非索引列 → 整个条件不走索引
WHERE status = 1 OR remark = 'urgent'

-- ① 改为范围查询
WHERE create_time >= '2026-07-20' AND create_time < '2026-07-21'

-- ② 保持类型一致
WHERE phone = '13800138000'

-- ③ 改为后缀模糊，或上 ES/搜索引擎
WHERE order_no LIKE 'ABC123%'

-- ④ 条件补上最左列，或调整索引列顺序
WHERE a = 1 AND b = 1 AND c = 2

-- ⑤ 拆成 UNION，两个分支各自走索引
SELECT ... WHERE status = 1
UNION
SELECT ... WHERE remark = 'urgent'

-- 开启慢查询日志（或写入 my.cnf 持久化）
SET GLOBAL slow_query_log = 'ON';
SET GLOBAL long_query_time = 1;              -- 超过 1 秒记录
SET GLOBAL slow_query_log_file = '/var/log/mysql/slow.log';

# 按执行次数排序，取最慢的 10 条
mysqldumpslow -s c -t 10 /var/log/mysql/slow.log

# 按总耗时排序
mysqldumpslow -s t -t 10 /var/log/mysql/slow.log

慢接口告警
   │
   ▼
【重点一】链路追踪：拆出每一跳耗时
   │  → 确定慢在哪个服务 / 哪次调用
   ▼
【重点二】服务层分析：线程池 / 连接池 / GC
   │  → 确定是资源耗尽还是代码执行慢
   ▼
【重点三】SQL 执行计划：EXPLAIN + 索引失效清单
   │  → 定位根因，改写 SQL，补索引
   ▼
开启慢查询日志常态化监控，防止复发