SkyWalking实战：从接口超时和内存告警到慢SQL与线程池排查

周五下午三点多，线上告警群突然弹出两条消息：接口P99耗时超过3秒，Java服务容器内存占用到了limit的85%还在继续往上涨。这台服务上线大半年一直很稳，突然又是超时又是内存告警，我没有直接翻代码，而是先打开SkyWalking看链路。结果花了一个多小时，从服务拓扑一路追到一条SQL和一处线程池配置，把两个问题都定位了。这篇就完整记录这次线上异常排查的全过程，重点讲我是怎么用SkyWalking一步步把问题范围从“整个服务”缩小到“一行代码”的，以及过程中趟过的一些坑，希望能给做Java后端、又想把APM排查思路弄明白的同学一些参考。

1. 故障初现：接口超时与容器内存告警

1.1 故障现场还原

先说背景。出问题的服务是order-service，负责订单查询和状态变更，部署在K8s集群里，Pod规格是4核8G，JVM堆设置4G，后置MySQL和Redis。这个服务平时很稳定，P99基本在200毫秒以内，所以告警一响，我的第一反应是“是不是有人动了配置”或者“是不是上游调用量突然变大”。

告警详情显示两条：

• HTTP接口/order/detail的P99达到3.2秒，成功率99.1%，不算完全挂掉，但明显已经影响用户查询体验；
• 容器内存从下午两点开始一路缓涨，到告警时已经到limit的85%，而且没有回落的趋势。

这种“接口变慢+内存缓涨”的组合非常典型。先说明一下，线上排查最忌讳一上来就翻代码，因为问题可能不在代码逻辑本身，而在调用链的某个环节。正确的做法是先看全局：流量有没有变化、依赖有没有抖动、JVM和系统资源有没有异常，把范围缩小后再去看代码。

当时我先看了一眼K8s层面的Pod状态和资源使用，CPU在60%左右波动，不算打满；磁盘和网络没看到明显异常。Pod没有重启，说明还没触发OOM Kill，但按这个涨法，再撑一两个小时就要出事。

1.2 为什么这次我直接选SkyWalking

市面上的APM工具不少，包括SkyWalking、Pinpoint、Zipkin、Jaeger，还有一些商业方案。我最终选SkyWalking作为日常排查主力，原因很朴素：

• 它对Java应用的接入成本极低，JavaAgent一把梭，业务代码零侵入；
• 拓扑图、调用链、JVM指标、数据库访问耗时全部在一个UI里能看到，省去到处切系统的麻烦；
• 开源社区活跃，资料多，团队内部也容易推行。

可能有人会说，看慢SQL可以直接开MySQL慢查询日志，看线程栈可以jstack，看内存可以JConsole，为什么非要上APM？我的体会是：单点工具只能告诉你在某个环节出了问题，而APM能告诉你在整条链路里问题出在哪一环。比如这次，接口变慢可能是网关、可能是Redis、可能是MySQL、也可能是服务自身的线程资源耗尽。没有链路追踪，你只能一个个去排查，运气不好可能要折腾一两个小时；有了SkyWalking，直接在Trace里看每个Span的耗时，一分钟就能定位到真正的瓶颈点。

这也是我写这篇文章的初衷：把一次真实故障排查的过程完整还原出来，不只是讲“我用了SkyWalking”，而是讲清楚在排查的每一个阶段，SkyWalking的哪个功能解决了我的什么问题。

2. 接入流程与第一个关键发现

2.1 快速接入的两种方式与配置

在讲排查过程前，先同步一下SkyWalking的接入方式。这次我们的order-service原来就已经接入SkyWalking了，版本是8.6.0，OAP部署在集群内部。如果你还在用8.x之前的版本，建议直接上9.x或者最新稳定版，新版本的UI和数据模型会好很多。

接入方式就是JavaAgent，在启动命令里加参数：

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

如果是K8s部署，通常会在Dockerfile或启动命令里预置agent路径，或者通过initContainer把agent文件挂载进Pod。这个Process是Java进程级注入，不需要改动任何业务代码，重启一次服务就生效。

补充一个容易忽略的点：agent版本和OAP服务端版本尽量保持一致，至少大版本要匹配。我们以前踩过坑，agent用的是8.9.0，OAP还是8.6.0，结果部分Trace数据上报不了，UI上看起来数据断断续续，排查了半天才发现是版本兼容问题。

2.2 接入后先看什么：拓扑图和服务健康度

打开SkyWalking UI，我第一个看的是拓扑图。拓扑图能帮你快速判断“当前服务的上下游都调了谁、谁被调得最频繁”，尤其在故障排查初期，这一屏信息比任何日志都直观。

这次order-service的拓扑并不复杂：上游是api-gateway，下游依赖user-service、MySQL和Redis。看到拓扑图一切正常，没有新的依赖冒出来，说明不是“上游新增调用导致雪崩”这类问题。

然后点进order-service的服务详情页，分三个维度看：

1. 服务存活状态：所有实例都是健康状态，没有OOM Kill记录；
2. Endpoint列表：按平均响应时间倒序排，/order/detail排第一，平均耗时接近2秒；
3. 实例性能面板：Heap Used在3.2G左右，堆内存分配正常，但容器内总内存使用率很高——这一步很关键，后面会详细说。

大家习惯上看完拓扑之后直接去翻服务日志，我建议先定位端点的响应时间，因为这是最能缩小范围的维度：问题到底集中在某个接口，还是所有接口都慢。如果是某个接口慢，大概率是代码逻辑或SQL问题；如果是所有接口都慢，大概率是服务实例资源或中间件问题。

我们这次属于前者，/order/detail是重灾区，其他接口也有轻微上升，说明问题是从这个接口往外扩散的，比如线程池被这个接口的慢请求占满了，其他接口只能排队。

3. 从慢Trace到一条SQL的定位过程

3.1 锁定慢接口，核对Trace结构

确认/order/detail是最慢的端点之后，我进入端点详情页，选了最近5分钟的慢请求Trace列表。SkyWalking的Trace视图会展示一条完整调用链，包含每个Span的Layer、组件类型、耗时、状态码。

我那会儿随便点开了一条耗时2.8秒的Trace，结构大概长这样：

这里有个很重要的点：Controller总耗时并不等于所有子Span耗时的简单相加，因为可能存在Span缺失、采样率不足、或者线程池异步调用导致子Span挂在别的线程上。我当时看到MySQL两条查询占了绝大部分时间，就知道问题基本锁定在数据库访问这一层了。

但有读者可能会问：为什么MySQL有两条查询？这两条SQL到底是什么？这时候单纯靠Trace的自定义信息还不够，需要进一步拿到真实SQL和执行计划。

3.2 数据库访问Span暴露出的真实开销

SkyWalking对MySQL的埋点会把SQL预览展示在Span信息里，包括SQL类型、数据库实例、当前SQL状态。我点开MySQL那个耗时最高的Span，看到SQL大致是这样：

SELECT id, order_no, user_id, status, total_amount, create_time FROM t_order WHERE status = 'PAID' AND order_no IN ( SELECT order_no FROM t_order_item WHERE sku_id = ? ) ORDER BY create_time DESC LIMIT 10

看到这个SQL，我基本能猜到问题方向了：外层表t_order的数据量在百万级，status='PAID'能过滤掉一部分数据，但过滤后剩下的量可能还是很大；order_no IN子查询的结果集如果在几百行以上，MySQL优化器可能不会走索引合并，而是选择全表扫或者产生临时表。ORDER BY create_time DESC如果没有合适的联合索引，还会触发filesort。

Trace里的2380ms基本都消耗在这条SQL上。

这时候我再确认一件事：这条SQL是不是真如猜测那样执行计划很差。我直接连上生产库（只读账号），用EXPLAIN跑了一下同类查询：

EXPLAIN SELECT id, order_no, user_id, status, total_amount, create_time FROM t_order WHERE status = 'PAID' AND order_no IN ( SELECT order_no FROM t_order_item WHERE sku_id = 12345 ) ORDER BY create_time DESC LIMIT 10;

结果如下：

看到type=ALL和rows=121万，定位就非常清楚了：t_order这条主查询是全表扫描，然后还有filesort排序。对于百万级数据的表，全表扫描加排序，慢是必然的。

到这里，第一阶段排查结束：慢接口 -> 慢Trace -> 慢SQL，链条完整。

4. 根因分析：SQL为什么慢、容器内存为什么涨

4.1 SQL根因：索引缺失与子查询方案选择问题

SQL慢的直接原因已经摆在眼前：t_order表上的status和order_no、create_time没有形成一个有效的索引组合，导致MySQL优化器选择了全表扫描加filesort。

具体来说是两个叠加问题：

1. status='PAID'的区分度不够。订单表中PAID状态占比很高，即使有status单列索引，优化器也大概率认为走索引不如全表扫描，所以宁可扫121万行也不用索引；
2. order_no IN子查询的结果集过大。内层子查询根据sku_id查出来的order_no有八百多行，而外层套了IN之后，主查询的行数估算没有显著下降，优化器最终选择了一条最“稳妥”但不高效的路。

这个时候的正确优化方式不是“把SQL改成别的写法”一了百了，而是要结合业务场景制定方案。我们的订单查询场景是：根据商品SKU找到对应的订单列表，按创建时间倒序分页展示。最合适的索引应该是：

ALTER TABLE t_order ADD INDEX idx_status_create_time (status, create_time);

这个索引的意图很明确：先用status把数据范围缩小，然后再用create_time满足排序，避免filesort。对于IN子查询，也可以考虑把子查询改写为JOIN，让MySQL用更稳定的驱动表顺序：

SELECT o.id, o.order_no, o.user_id, o.status, o.total_amount, o.create_time FROM t_order o INNER JOIN ( SELECT DISTINCT order_no FROM t_order_item WHERE sku_id = ? ) item ON o.order_no = item.order_no WHERE o.status = 'PAID' ORDER BY o.create_time DESC LIMIT 10;

但要注意，索引能否生效还取决于数据分布，线上执行EXPLAIN验证是必须的步骤。我不是建议你们直接照抄这个索引，而是说排查的时候脑子里要有一个思路：大表查询慢，优先从执行计划和索引设计入手而不是急着改代码。

这里也顺便提一下：SkyWalking本身不会告诉你“SQL应该怎么优化”，但它能把慢SQL的现场完整保留下来，让你把排查范围从整个接口收敛到一条SQL上。如果没有Trace数据，DBA给你一条慢查询日志，你还得猜这个SQL是哪个接口在哪个条件下发出来的；有了链路追踪，SQL和调用方TraceId是绑定在一起的，上下文一目了然。

4.2 内存问题：SkyWalking的JVM视图和容器态之间的落差

SQL的问题定位完，另外一个问题还悬着：容器内存为什么会持续上涨？

继续看SkyWalking的实例监控面板，我发现一个有意思的细节：JVM的Heap Used稳定在3.2G左右，GC也很正常，老年代回收后内存能降下来；但容器总内存却从5G涨到6.8G，而且没有回落的迹象。

容器内存和JVM堆内存之间这个差值，就是堆外内存的足迹。

Java进程的占用不只是堆内存，还包括Metaspace、线程栈、DirectByteBuffer（堆外内存）、网络缓冲区、JIT编译器相关的内存，以及一些Native内存。常见的高发区有两个：

1. Netty/DirectByteBuffer：如果使用了Netty、或者基于Netty的框架（比如gRPC、WebFlux），堆外内存分配过多会导致容器内存缓涨；
2. 线程数量膨胀：每个线程默认栈大小1MB左右，线程数从200涨到800，光是线程栈就多占600MB。

SkyWalking里能看到的指标是线程数量和JVM GC趋势。我当时看到线程数从平时的300左右涨到了850，而且GC频率也变高了，CPU却没有打满。这个组合很蹊跷：GC频繁说明对象不断被创建和丢弃，线程数大涨说明很可能有任务在排队或者阻塞。

结合 /order/detail 这个接口的业务逻辑，我翻代码发现了嫌疑点：这个接口里有一个自定义的线程池，用来做异步数据聚合和通知推送。代码如下：

private final ExecutorService notifyExecutor = new ThreadPoolExecutor( 4, 8, 60L, TimeUnit.SECONDS, new LinkedBlockingQueue<>() );

注意这个LinkedBlockingQueue<>()，没有指定容量，也就是无界队列。无界队列意味着核心线程满之后，新任务不是创建新线程，而是全部塞进队列里排队。队列越堆越长，任务持有的对象数据一直存活，内存自然只升不降。

这里的排查思路值得多聊两句：一个慢接口在数据库查询慢的同时，会把一批批SQL结果集交给线程池做后续异步处理；因为SQL慢，任务处理速度更不上，加上无界队列缓冲，积压的任务越来越多，内存涨、线程涨、GC涨。慢SQL是导火索，线程池是无界队列是放大镜。如果只修SQL不修线程池，问题可能只是从“内存告警”变成“偶发抖动”，但没有从根源上消除隐患。

定位到这一步之后，再回头看SkyWalking的堆外内存曲线，就顺理成章了。它不能像NMT（Native Memory Tracking）那样精确告诉你堆外哪里占了多少，但结合线程数、GC趋势和业务代码，足够帮你锁定怀疑方向。

5. 优化落地与后续使用体会

5.1 修复方案与指标恢复

这次修复分两条线推进：

SQL侧，给t_order加了idx_status_create_time (status, create_time)联合索引，并把IN子查询改写为JOIN派生表。上线执行EXPLAIN验证：

主查询从121万行降到1240行，filesort消失，查询时间从2.4秒降到了80毫秒左右。接口P99当天回落到220毫秒，之后稳定在180毫秒上下。

线程池侧，改成了有界队列外加调用者执行策略：

private final ExecutorService notifyExecutor = new ThreadPoolExecutor( 4, 8, 60L, TimeUnit.SECONDS, new ArrayBlockingQueue<>(200), new ThreadPoolExecutor.CallerRunsPolicy() );

CallerRunsPolicy的意思是：当队列满的时候，不在线程池里执行任务，而是让提交任务的线程自己去执行，相当于一种背压机制。这样不会丢任务，也不会无限积压内存，代价是接口响应时间在极端情况下会稍微变长，但不会导致整个服务崩掉。

这个优化上线后，容器内存稳定在5G左右，线程数回落到300多，告警彻底消失。

5.2 SkyWalking日常使用中的几个提醒

这次排查之后，我把SkyWalking的一些使用经验整理了一下，真的建议团队里的同学看完：

1. 采样率不要调太低。SkyWalking的采样策略默认是每3秒采样固定数量，如果压测或者高流量下你发现Trace经常查不到数据，很可能是采样把关键请求丢掉了。排查线上问题本来就是靠样本，低采样率影响非常大。

2. 一定要把TraceId和业务日志打通。这次排查过程中，我看到Trace里某条SQL的执行时间异常，但由于日志里没有TraceId，我花了额外时间去日志系统里捞对应的调用记录。后来接入logback插件，在日志pattern里加一段%X{tid}，日志输出里就有SkyWalking的TraceId了。以后接到任何报错，日志搜TraceId，链路直接拉出来，效率提升明显。

3. 告警规则是必须配的，不是可选项。这次能快速发现P99异常，就是因为之前配了endpoint响应时间告警。在alarm-settings.yml里可以定义规则：

rules: - name: endpoint-rt-rule metric-name: endpoint_avg op: ">" threshold: 2000 period: 10 count: 3 message: 端点平均响应时间超过2秒

不配告警的监控系统形同虚设，出了问题只能靠用户投诉，那就太被动了。

4. JVM监控看趋势比看瞬时值重要。瞬时GC时间高不一定有问题，要看是否持续增长；堆内存占用高不一定是泄漏，看GC后能否回落到正常水位。SkyWalking提供的是分钟级趋势数据，用来做方向判断非常合适，但真要深挖堆内对象分布，还是得配合heap dump和MAT去分析。

5.3 个人体会：APM帮的是“缩小范围”，不是“替代思考”

最后说几句实在话。很多人以为线上出了问题，打开SkyWalking就能直接看到“错在这里”，这是误解。SkyWalking的价值在于它把“网络、中间件、数据库、JVM、代码”这些层面的线索合并到一张图一张链路上，帮你把排查范围从“全服务”缩小到“一个接口”再到“一条SQL”或者“一处线程池配置”。

这次的经历里，如果没有SkyWalking，我大概率还在慢日志和日志文件中翻找哪条SQL是哪个请求触发的，更别说把内存问题和慢SQL关联起来了。但即使有APM工具，根因判断还是得靠基本的数据库知识、JVM内存模型和并发常识。工具是放大镜，你自己得知道往哪里看。

如果你现在还在犹豫要不要在项目里接入SkyWalking，我的建议很直接：新服务上线前就把agent接上，告警规则调好，日志TraceId打通。平时可能一个月都用不上一次，但真出问题的时候，它能帮你省下半天到一天的排查时间——这绝对是一笔划算的账。