周五下午三点多线上告警群突然弹出两条消息接口P99耗时超过3秒Java服务容器内存占用到了limit的85%还在继续往上涨。这台服务上线大半年一直很稳突然又是超时又是内存告警我没有直接翻代码而是先打开SkyWalking看链路。结果花了一个多小时从服务拓扑一路追到一条SQL和一处线程池配置把两个问题都定位了。这篇就完整记录这次线上异常排查的全过程重点讲我是怎么用SkyWalking一步步把问题范围从“整个服务”缩小到“一行代码”的以及过程中趟过的一些坑希望能给做Java后端、又想把APM排查思路弄明白的同学一些参考。1. 故障初现接口超时与容器内存告警1.1 故障现场还原先说背景。出问题的服务是order-service负责订单查询和状态变更部署在K8s集群里Pod规格是4核8GJVM堆设置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.0OAP部署在集群内部。如果你还在用8.x之前的版本建议直接上9.x或者最新稳定版新版本的UI和数据模型会好很多。接入方式就是JavaAgent在启动命令里加参数java -javaagent:/opt/skywalking-agent/skywalking-agent.jar \ -Dskywalking.agent.service_nameorder-service \ -Dskywalking.collector.backend_serviceskywalking-oap:11800 \ -jar order-service.jar如果是K8s部署通常会在Dockerfile或启动命令里预置agent路径或者通过initContainer把agent文件挂载进Pod。这个Process是Java进程级注入不需要改动任何业务代码重启一次服务就生效。补充一个容易忽略的点agent版本和OAP服务端版本尽量保持一致至少大版本要匹配。我们以前踩过坑agent用的是8.9.0OAP还是8.6.0结果部分Trace数据上报不了UI上看起来数据断断续续排查了半天才发现是版本兼容问题。2.2 接入后先看什么拓扑图和服务健康度打开SkyWalking UI我第一个看的是拓扑图。拓扑图能帮你快速判断“当前服务的上下游都调了谁、谁被调得最频繁”尤其在故障排查初期这一屏信息比任何日志都直观。这次order-service的拓扑并不复杂上游是api-gateway下游依赖user-service、MySQL和Redis。看到拓扑图一切正常没有新的依赖冒出来说明不是“上游新增调用导致雪崩”这类问题。然后点进order-service的服务详情页分三个维度看服务存活状态所有实例都是健康状态没有OOM Kill记录Endpoint列表按平均响应时间倒序排/order/detail排第一平均耗时接近2秒实例性能面板Heap Used在3.2G左右堆内存分配正常但容器内总内存使用率很高——这一步很关键后面会详细说。大家习惯上看完拓扑之后直接去翻服务日志我建议先定位端点的响应时间因为这是最能缩小范围的维度问题到底集中在某个接口还是所有接口都慢。如果是某个接口慢大概率是代码逻辑或SQL问题如果是所有接口都慢大概率是服务实例资源或中间件问题。我们这次属于前者/order/detail是重灾区其他接口也有轻微上升说明问题是从这个接口往外扩散的比如线程池被这个接口的慢请求占满了其他接口只能排队。3. 从慢Trace到一条SQL的定位过程3.1 锁定慢接口核对Trace结构确认/order/detail是最慢的端点之后我进入端点详情页选了最近5分钟的慢请求Trace列表。SkyWalking的Trace视图会展示一条完整调用链包含每个Span的Layer、组件类型、耗时、状态码。我那会儿随便点开了一条耗时2.8秒的Trace结构大概长这样Span类型操作名耗时Controller/order/detail2805msRedisGET order:detail:{id}160msMySQLSELECT ... FROM t_order_item2380msMySQLSELECT ... FROM t_order2450ms这里有个很重要的点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的数据量在百万级statusPAID能过滤掉一部分数据但过滤后剩下的量可能还是很大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;结果如下select_typetabletypepossible_keyskeyrowsExtraPRIMARYt_orderALLNULLNULL1210000Using where; Using filesortDEPENDENT SUBQUERYt_order_itemrefidx_sku_idNULL847NULL看到typeALL和rows121万定位就非常清楚了t_order这条主查询是全表扫描然后还有filesort排序。对于百万级数据的表全表扫描加排序慢是必然的。到这里第一阶段排查结束慢接口 - 慢Trace - 慢SQL链条完整。4. 根因分析SQL为什么慢、容器内存为什么涨4.1 SQL根因索引缺失与子查询方案选择问题SQL慢的直接原因已经摆在眼前t_order表上的status和order_no、create_time没有形成一个有效的索引组合导致MySQL优化器选择了全表扫描加filesort。具体来说是两个叠加问题statusPAID的区分度不够。订单表中PAID状态占比很高即使有status单列索引优化器也大概率认为走索引不如全表扫描所以宁可扫121万行也不用索引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内存。常见的高发区有两个Netty/DirectByteBuffer如果使用了Netty、或者基于Netty的框架比如gRPC、WebFlux堆外内存分配过多会导致容器内存缓涨线程数量膨胀每个线程默认栈大小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的堆外内存曲线就顺理成章了。它不能像NMTNative Memory Tracking那样精确告诉你堆外哪里占了多少但结合线程数、GC趋势和业务代码足够帮你锁定怀疑方向。5. 优化落地与后续使用体会5.1 修复方案与指标恢复这次修复分两条线推进SQL侧给t_order加了idx_status_create_time (status, create_time)联合索引并把IN子查询改写为JOIN派生表。上线执行EXPLAIN验证select_typetabletypekeyrowsExtraPRIMARYorefidx_status_create_time1240Using wherePRIMARYderived2ALLNULL860Using where; Using join bufferDEPENDENT SUBQUERYt_order_itemrefidx_sku_id840NULL主查询从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的一些使用经验整理了一下真的建议团队里的同学看完采样率不要调太低。SkyWalking的采样策略默认是每3秒采样固定数量如果压测或者高流量下你发现Trace经常查不到数据很可能是采样把关键请求丢掉了。排查线上问题本来就是靠样本低采样率影响非常大。一定要把TraceId和业务日志打通。这次排查过程中我看到Trace里某条SQL的执行时间异常但由于日志里没有TraceId我花了额外时间去日志系统里捞对应的调用记录。后来接入logback插件在日志pattern里加一段%X{tid}日志输出里就有SkyWalking的TraceId了。以后接到任何报错日志搜TraceId链路直接拉出来效率提升明显。告警规则是必须配的不是可选项。这次能快速发现P99异常就是因为之前配了endpoint响应时间告警。在alarm-settings.yml里可以定义规则rules: - name: endpoint-rt-rule metric-name: endpoint_avg op: threshold: 2000 period: 10 count: 3 message: 端点平均响应时间超过2秒不配告警的监控系统形同虚设出了问题只能靠用户投诉那就太被动了。JVM监控看趋势比看瞬时值重要。瞬时GC时间高不一定有问题要看是否持续增长堆内存占用高不一定是泄漏看GC后能否回落到正常水位。SkyWalking提供的是分钟级趋势数据用来做方向判断非常合适但真要深挖堆内对象分布还是得配合heap dump和MAT去分析。5.3 个人体会APM帮的是“缩小范围”不是“替代思考”最后说几句实在话。很多人以为线上出了问题打开SkyWalking就能直接看到“错在这里”这是误解。SkyWalking的价值在于它把“网络、中间件、数据库、JVM、代码”这些层面的线索合并到一张图一张链路上帮你把排查范围从“全服务”缩小到“一个接口”再到“一条SQL”或者“一处线程池配置”。这次的经历里如果没有SkyWalking我大概率还在慢日志和日志文件中翻找哪条SQL是哪个请求触发的更别说把内存问题和慢SQL关联起来了。但即使有APM工具根因判断还是得靠基本的数据库知识、JVM内存模型和并发常识。工具是放大镜你自己得知道往哪里看。如果你现在还在犹豫要不要在项目里接入SkyWalking我的建议很直接新服务上线前就把agent接上告警规则调好日志TraceId打通。平时可能一个月都用不上一次但真出问题的时候它能帮你省下半天到一天的排查时间——这绝对是一笔划算的账。