ARTICLE DETAIL

资讯详情

深耕网站视觉设计与运营推广的一线实战洞察。

接口变慢怎么办?APM与链路追踪的完整排查实战

接口变慢怎么办?APM与链路追踪的完整排查实战 接口变慢这事干过后端的都懂。明明昨天还好好的今天一上班监控就报“获取用户详情”接口p99从120ms飙到3秒用户侧已经在群里炸了。你第一反应是打开服务器日志结果翻了几百MB日志只看到一堆正常返回根本不知道慢在哪。这时候APMApplication Performance Monitoring应用性能监控就是那个帮你把“慢”拆开看的东西——它不是直接告诉你“该改哪行代码”但能告诉你一次请求从入口进来网关花了多久、服务A调服务B花了多久、MySQL查了多久、Redis读了几次所有环节的耗时被一一摊开。这篇文章就围绕“接口变慢了APM到底该怎么查”这件事把我自己排查慢接口的完整套路、常用工具和踩过的坑一次说清楚适合后端开发、运维、SRE以及那些被“接口突然变慢”折磨过的人。1. 接口变慢APM到底能帮你看到什么1.1 一个典型的接口变慢现场说个我经历过的真实场景。某天下午业务方反馈用户中心一个“获取用户详情”的接口明显变慢客户端转圈超过3秒。当时我们刚上APM不久我打开链路追踪页面搜这个接口最近一小时的调用记录点开一条耗时2.8秒的Trace第一时间就看到了完整调用链入口HTTP网关耗时2.8秒往下是用户服务本地方法耗时2.8秒再往下MySQL查询耗时2.4秒Redis查询耗时60毫秒一次外部会员系统的RPC调用耗时30毫秒。看到这个结果问题范围立刻从“整个接口慢”缩小到“MySQL查询慢”而且耗时集中在一条具体的SQL上。后续配合数据库慢查询日志发现这条SQL因为WHERE条件里字段类型不匹配导致索引失效走了全表扫描。整个过程从打开APM到定位到具体SQL花了不到十分钟。换成以前靠人肉翻日志猜原因这时间连日志都还没读完。这就是APM的价值它把一次请求拆成一段段带计时的“Span”用一个树状结构把整个调用链路还原出来谁耗时多、谁报错了、谁在等谁一目了然。你不需要去猜只需要顺着耗时最长的分支一路往下点。1.2 链路追踪类APM的核心能力拆解市面上常见的APM工具不管是SkyWalking、Pinpoint、Zipkin还是Jaeger核心模型都是Trace和Span。Trace代表一次完整的请求从客户端发出开始到服务端响应结束Span是Trace里的一个片段可以理解成一次具体的操作——一次HTTP调用、一次RPC调用、一次数据库查询、一个本地方法执行。多个Span按父子关系组成一棵树根Span就是入口请求子Span就是它在内部发起的各种调用。打个比方Trace就是一条完整的生产线流程Span就是每个工位上具体在干哪件事。整条产线总共花了3分钟你一眼就能看到“焊接”这个工位占了2分40秒那问题大概率就在焊接环节。APM的查询界面通常支持按接口名、TraceID、时间段、耗时阈值去检索结果列表里每条Trace会显示总耗时和状态点进去就是Span树。除链路视图外好的APM还提供服务拓扑图把服务之间的调用关系画出来箭头粗细代表调用量的多少颜色代表健康状态。排查接口变慢时拓扑图能快速帮你看清“被调服务本身慢了”还是“调用链路上某个环节慢了”避免来回切换服务看数据。1.3 APM看不出来的部分别指望它解决一切APM虽然能定位到“哪段慢”但很多时候它不能直接告诉你“为什么慢”。比如一个本地Java方法在Span上显示耗时800毫秒但方法内部是普通的字符串拼接、循环、序列化、加锁这些细粒度的时间分布链路追踪是看不到的。再比如一次Full GC造成的全局停顿Span显示是某行代码耗时长但真实原因是JVM在垃圾回收跟那行代码没半毛钱关系。所以在实际排查中APM只是第一层入口帮你缩小范围。定位到具体服务、具体方法之后还得结合性能剖析工具Arthas、async-profiler、数据库慢查询日志、JVM监控、系统层监控一起查。我的经验是APM负责“哪一段慢”profiling工具负责“这一段里哪行代码慢”系统监控负责“是不是机器、容器、依赖的资源出了问题”。三者配合基本能把90%的慢接口原因挖出来。2. 排查前先选对工具链路追踪与性能剖析怎么搭档2.1 链路追踪工具怎么选选APM工具这事我见过太多团队一上来就同时调研好几个最后陷入选择困难。先别想哪个“最好”先看三类硬约束第一接入方式是不是无侵入Java技术栈能不能用Agent自动埋点不用改业务代码第二存储和部署成本很多APM要依赖Elasticsearch没有ES集群的团队部署成本会高不少第三UI是否成熟团队里不是每个人都愿意用命令行看数据一个直观的Web界面能极大降低使用门槛。我实际对比过几款主流工具。SkyWalking是Java技术栈的无侵入方案Agent一挂就能自动采集HTTP、RPC、数据库、消息队列等组件的调用链路UI自带拓扑图和告警对国内团队比较友好Pinpoint也是Java Agent类工具链路分析做得很细能看到方法级的调用耗时但部署相对重一些Zipkin和Jaeger更偏底层链路追踪通常和OpenTelemetry配合使用灵活性强但需要自己在业务代码里加埋点或者额外配置 instrumentation适合已经有基础可观测体系、想深度定制数据的团队CAT是大众点评开源的老牌APM功能很强但接入和运维复杂度不低。如果团队规模不大、Java技术栈为主、想快速见效我的建议是从SkyWalking入手一键部署后端服务Java服务挂上Agent几分钟就能看到链路数据。没必要在一开始搞一套“全家桶”先解决“有没有数据”的问题再谈“数据够不够精细”。2.2 性能剖析工具是APM的重要补充APM把慢接口定位到某个方法后经常遇到“这个方法里逻辑好多到底哪一行是热点”的困境。这时候就需要性能剖析工具出场。Java领域我常用的有Alibaba Arthas和async-profiler。Arthas是一款Java诊断工具它不需要重启服务可以直接在线上环境执行命令。最常用的命令是trace比如trace com.example.UserService getDetail它会打印这个方法内部每个子调用的耗时分布精确到单个方法、单行逻辑还有watch可以观测方法入参和返回结果排查是不是特定参数导致走了慢分支thread -n 3可以列出最忙的几个线程看它们的栈发现线程卡在什么地方。async-profiler则是基于JVM内部事件采集的CPU火焰图工具能生成方法级的CPU热点图特别适合定位“CPU飙高导致接口变慢”的场景。关于什么时候用哪个我的习惯是先看APM确定“哪个服务哪个接口哪个方法慢”再用Arthas trace做方法级下钻如果发现是CPU高导致整体慢就上async-profiler抓火焰图如果怀疑GC问题配合jstat -gcutil看GC频率和停顿时间。这些工具不是APM的替代品而是它的显微镜。2.3 我建议的低成本组合踩过不少坑之后我现在推荐的低成本高性价比组合是这样一套第一层是APM链路追踪选SkyWalking负责接口维度的耗时分布、调用链、拓扑发现和告警第二层是基础监控用Prometheus加Grafana负责服务器CPU、内存、磁盘、网络以及JVM的堆内存、GC、线程数第三层是数据库侧MySQL开慢查询日志配合Druid或HikariCP的监控面板看连接池状态第四层是备用诊断工具Arthas装好出问题随时上服务器trace。这套组合加起来投入不大但刚好覆盖了“入口-服务内部-数据库-机器资源”的完整链条。还有一点要提醒不要同时上两套APM。我见过有团队先在测试环境装了一套SkyWalking后来觉得Jaeger更“潮流”又上了Jaeger结果同一个服务挂了两个Agent数据对不上资源开销还翻倍。APM这玩意儿选定一套用熟它比反复横跳有用得多。3. 一步步来一个慢接口的完整排查流程3.1 第一步先确认到底多慢建立基准拿到“接口变慢”的反馈先别急着打开APM查链路。停下来想三件事第一慢是偶发还是持续是从什么时间点开始的当时有没有发版、变更配置、增加数据量第二慢是均匀变慢还是个别请求特别慢这里有本质区别均匀变慢通常指向资源或依赖出了问题个别请求特别慢则往往是特定数据、特定参数触发的第三影响面有多大只影响这个接口还是整个服务、整个集群都受影响。“到底多慢算慢”也得定义清楚。同一个接口平均耗时100毫秒和p99耗时3秒传递的信息完全不同。看耗时一定要分位数视角p50代表大多数用户的体验p95和p99才是真正的长尾风险。很多团队只盯着平均值结果平均值看起来没涨多少实际上很多用户已经在忍受超时。我通常的做法是先看这接口的p99和p95曲线如果它们和p50一起上涨问题多半是全局性的如果只有p99涨、p50变化不大那就是长尾请求拖慢的得重点看超时和重试。3.2 第二步打开Trace找出最耗时的那个Span确认完基本盘进入APM后台按接口名搜索慢调用按耗时倒序排列点开一条典型的慢Trace看Span树。操作方法每个APM工具略有不同但思路一致找到总耗时最长的那条链路然后从上往下找耗时占比最大的子Span。这里有个关键技巧不要只看第一个慢Span要看完整链路。比如一个HTTP接口耗时2秒下面第一个Span是调用用户服务的RPC花了1.9秒你以为用户服务慢了点进用户服务的Trace才发现它的耗时主要是查数据库。链路追踪的价值就在于你能顺着跨进程调用一层层往下钻直到看到最底层的那个“真正耗时大户”。如果是数据库Span通常会有SQL语句和数据库类型直接复制SQL去数据库执行一次看基础执行时间如果是外部HTTP/RPC调用看下游服务的链路是否也有记录有就跳过去继续追没有就说明下游没有接入APM这时候只能靠下游自己的日志或监控来核实。我遇到过不少次点开Trace第一眼看到的不是数据库而是本地方法这时不要忽略它。本地方法慢有时隐藏着大问题比如一次大对象序列化、一次加锁竞争、一次循环里的远程调用。用Arthas trace再往下钻一层往往能发现真正的原因。3.3 第三步按大头类型逐层下钻SQL、外部依赖、本地代码看到耗时大头之后根据类型走不同的排查路径。如果大头是SQL优先去数据库看慢查询日志拿到完整的SQL和实际执行计划用EXPLAIN分析是不是全表扫描typeALL、有没有命中索引key是否为null、预估扫描行数有多大、有没有隐式类型转换、是不是被锁等待卡住。很多慢SQL一眼就能看出问题比如字段类型不匹配导致索引失效比如深分页limit 100000,20扫描了大量数据。SQL这块在下一节我会展开讲因为它是接口变慢出现频率最高的根因。如果大头是外部依赖调用比如第三方HTTP接口、下游微服务、消息队列先确认超时时间和重试策略——有些调用默认超时10秒下游只要不返回线程就一直在等还有重试机制第一次超时后立刻重试相当于把流量放大一倍。排查时看Trace里这个调用的状态码、耗时分布和失败率再结合下游自己的监控确认是“下游真的慢”还是“我们的超时设置不合理”。另外要警惕串行调用比如一个方法里连续调了三个下游接口每个都花200毫秒串行就是600毫秒如果可以并行耗时能直接降到200毫秒左右。如果大头是本地方法用Arthas trace跟进去。我见过最多的场景是循环里做了不必要的数据库查询N1问题、序列化了大对象、在synchronized锁里做了耗时操作、日志打印过多导致磁盘IO拥堵。火焰图在CPU热点定位上非常直观方法宽度代表占用时间的比例一眼锁定最宽的那块。如果是GC引起的jstat -gcutil看到FGC频繁且停顿时间高就得检查堆内存配置和对象分配速率。3.4 第四步修复后怎么验证才算真的好了修复完成后别急着宣布“搞定了”。先回APM看接口耗时曲线是否回落到基线水平p99、p95、p50三个分位数都要看不能只看平均值然后观察一段时间确认没有引起新的问题比如加了缓存后数据一致性有没有受影响改了SQL后有没有包袱其他慢查询。如果团队有基于JMeter或者自建接口自动化框架的用例直接把这条接口的回归用例跑一遍。自动化用例的用处不只是验证功能还能在修复后证明“接口在负载下没有重新变慢”。我习惯把修复过程里用的压测命令记下来下次再遇到同类问题可以直接复用。另外排查期间可能有人工重试、自动化监控探针等额外流量打进系统验证时要注意区分正常业务流量和排查期间产生的流量别把重试流量当成新出现的慢请求也别由此误判修复效果。4. 高频根因实录接口变慢最常见的几种元凶4.1 慢SQL索引失效、深分页、抢锁慢SQL是接口变慢的头号元凶这一点在微服务和单体应用里都一样。常见的情况有这么几类。索引失效。最典型的是字段类型不匹配引发的隐式类型转换。我以前遇到过一次用户表user_id字段是varchar类型查询条件传的是数字MySQL会先把字段转成数字再比较导致索引失效走了全表扫描。这种问题在APM里表现为SQL Span耗时飙升但SQL语句本身看不出明显问题只有EXPLAIN才能发现type从ref变成了ALL。深分页。分页查询ORDER BY create_time DESC LIMIT 100000, 20数据库需要先扫出前100020条记录再抛弃前100000条数据量一大哪怕有索引也很慢。解决办法一般是改成基于游标的分页方式或者通过子查询先拿到主键再回表查数据。大字段查询。SELECT * 把一个包含大text字段的表全部查出来网络传输和内存占用都会拖慢接口。这种情况在APM上能看到数据库Span耗时不低但执行计划可能走索引看起来正常实际问题是返回的数据量太大。锁等待。行锁、间隙锁没及时释放后面的查询全部在等待。APM会显示SQL耗时高但单独执行这条SQL可能又很快——因为现场已经释放锁了。这时候要去看数据库当前的锁等待和事务状态通常配套InnoDB的状态信息能看出端倪。4.2 外部依赖拖慢第三方接口与下游服务的锅“你的接口慢不代表你的代码有问题”这句话在排查外部依赖的慢接口时特别适用。常见的模式是你的服务调用了某个第三方接口比如微信支付下单、短信验证码下发对方某个时间段变慢或者不稳定你的接口只能跟着慢。如果超时时间没配好默认10秒对方的接口一直挂着不返回你的线程就会被白白占住请求一多线程池就满了整个服务的其他接口也跟着遭殃。排查这类问题APM同样是好帮手。在Trace里能看到外部调用的耗时、返回码和耗时分布如果发现对方接口偶尔报错、偶尔超时还要检查是否有重试机制放大了请求量。我踩过坑的场景是某个服务调用短信接口超时后自动重试重试间隔设得很短结果对方接口本来只是抖动被我们的重试打得更慢形成恶性循环。看外部依赖慢还有一层注意区分“调用方慢”和“被调方慢”。有时Trace显示下游RPC耗时高但下游服务的入口APM数据显示正常这时候要看看是不是网关层加了额外处理或者网络传输耗时本身很大比如跨机房调用。4.3 代码热点序列化、加锁、循环里的IO代码侧的慢通常在并发上来了以后才暴露。典型的有N1问题循环里逐个查询数据库或者调用远程服务一次请求产生几十上百次IO每条20毫秒加起来就是好几秒。APM可以看到这个方法整体耗时很高但如果你的APM不支持方法级下钻就得靠Arthas trace看方法内部到底调了几次数据库。序列化和日志也是隐藏元凶。高频接口里如果每次都序列化一个大对象返回给前端或者日志框架为了一条debug日志把大对象toString了一遍虽然单次看起来只有几十毫秒但QPS高的时候会持续消耗CPU。还有一种常见情况是加锁范围过大本该只锁一行数据的同步块把整个方法都锁了接口并发稍微一高就全排到锁上APM显示本地方法耗时高Arthas抓线程栈会看到大量线程处于BLOCKED状态。日志打太多这个问题我特别想说一下。有些团队为了排查方便在每个接口里把入参、出参、中间状态全打出来一次请求几百行日志。在高QPS场景下同步日志的磁盘IO会成为真正的瓶颈接口变慢的时间和日志量成正比。如果你在APM里看到耗时分散在各段没有一个明显的Span是大头那大概率是日志或者序列化这类“横切”开销拖慢了整体——这时候用火焰图看CPU热点往往一眼就能找到答案。4.4 基础设施抖动GC、连接池、CPU限流接口变慢也可能是“底层撑不住”导致的。JVM频繁Full GC会停顿整个应用轻则几十毫秒重则几秒期间所有请求都卡住。APM里能看到的方法耗时高其实只是表象。排查GC问题用jstat -gcutil pid看FGC次数和FGCT时间如果看到FGC增长很快、FGCT持续增加基本可以确认慢的根源就是GC停顿。常见诱因是堆内存太小、创建了大量生命周期长的对象、或者有内存泄漏需要用jmap或其他工具分析堆转储。连接池耗尽也很常见。数据库连接池和HTTP连接池都会“用完”。池里连接被占满后续请求只能排队等连接体现在APM上有两种情况一是数据库Span显示耗时高但SQL本身很快二是本地方法耗时高但看不到具体逻辑因为线程卡在获取连接上。排查方法很简单看连接池的监控指标active数量是否逼近上限、等待获取连接数是否上涨。HTTP连接池同理如果下游连接池满了调用方线程会堆积在等待连接的队列里。容器环境的CPU限流也要留意。Kubernetes里Pod的CPU limit设置过小或者节点上CPU争抢严重线程的调度延迟会明显增加。这种情况下的特征是服务本身的应用指标看起来正常但接口耗时整体上涨同时间段系统CPU使用率却不高——不是不忙而是被限制住了。4.5 缓存失效穿透、击穿、雪崩的连锁反应缓存的坑在于它不是“每天都慢”而是会在某个时间点突然爆发。最典型的是缓存集中过期一批数据的过期时间都设置在同一个时间点比如零点或者每小时整点到期后缓存里没有数据所有请求同一时间打向数据库数据库瞬间被压垮接口一个接一个变慢。APM在这种场景下的表现是Redis的Span耗时并不高但紧接着数据库查询的Span突然暴涨而且分布在同一时间窗口。如果看服务拓扑图会发现数据库的调用量在那一瞬间成倍放大。处理上一是给缓存过期时间加随机偏移避免“同时过期”二是对热点数据用“永不过期后台刷新”的策略三是用分布式锁或者单飞模式防止缓存穿透时的并发打到数据库。还有一种情况要特别注意接口的重试机制和缓存抖动叠加。比如接口内部先查缓存未命中后查数据库数据库慢了触发上层重试重试请求又找不到缓存再次打向数据库放大故障。排查的时候要盯着Trace排查这些“本来不该有的重复请求”。这也是为什么我一直强调排查慢接口一定要把重试逻辑纳入视野否则很容易被表象数据误导。5. APM排查最容易踩的坑5.1 只看平均值长尾问题全被淹没了平均值是APM看板里最容易误导人的一个指标。我举个例子100个请求99个都是1毫秒返回剩下1个卡了10秒平均值大约是100毫秒看平均值你根本不会觉得这个接口有问题但实际有1%的用户在忍受10秒超时。真正判断“接口是不是慢”必须看分位数特别是p95和p99。我习惯在APM的看板上把耗时曲线默认设置为p50、p95、p99三条线告警阈值也按p99设置而不是平均值。平均值只作为参考不作为决策依据。在实际排查慢接口时更要学会只看p99大于阈值的请求从这些“最差请求”里找规律比如它们是否集中在某个用户、某个商户、某个数据量较大的记录上——这一步往往能直接命中根因。5.2 采样率太低慢请求根本没录到有些团队为了省存储把APM的采样率调成1%上线后发现接口变慢了想查Trace结果发现慢请求绝大多数没有记录。这个问题特别普遍尤其是业务量大的系统全量采样的数据量确实吓人但完全不采样又等于白上APM。正确的做法是根据业务特性设置采样策略。如果接口QPS很高日常采10%足够用于趋势分析但如果遇到线上故障要定位临时把采样率调整到100%等定位完再调回去。另外现在主流的APM基本都支持“慢请求全量采样”的配置比如设置超过500毫秒的请求100%记录普通请求按比例采样。这样既能保证遇到问题时有数据可查又不会让存储开销爆炸。5.3 只盯入口耗时不去追跨服务调用接口A慢入口Span肯定慢但真正的问题可能在它下游调用的服务B、C甚至D。如果你停在A的Trace上看到有几个子Span的耗时比较高但没有跳转进下游服务查看它自己的内部链路就可能被误导到“A的代码有问题”上。我在排查时一直坚持“跨进程调用必须追到底”的原则Trace里的每个RPC/HTTP Span如果下游服务接了APM就点进去继续看如果没接就让负责那个服务的同事一起查或者看它自己的日志。曾经有一次A服务调B服务接口B服务耗时1.5秒我们差点在A服务里加缓存优化后来发现B服务慢是因为它去调一个已经废弃的旧服务每次都在等超时。如果当时不看下游链路这个坑不知道要埋多久。5.4 探针开销与统计口径的坑APM的探针虽然无侵入但不代表零开销。Java Agent模式下字节码增强会对方法调用产生一定性能影响通常控制在5%以内但如果你同时挂两个APM Agent或者某个高频方法被过度埋点开销可能明显上涨。我遇到过一个小型服务挂了APM后接口耗时多了30ms排查半天发现是探针对一个每秒调用数万次的方法做了全量埋点。解决办法是尽量使用APM的“关键链路埋点”功能只对业务关键路径做跟踪。统计口径的坑也值得一提。不同APM对“响应时间”的定义可能不同有的包含排队时间有的只计算实际处理时间有的把网关层耗时算进去有的不算。同一个接口在网关监控里看到的耗时和APM里看到的耗时对不上别急着怀疑工具不对先确认它们的口径是否一致。另外多台机器之间时钟不同步会导致跨进程Span的耗时出现负数或者异常大APM显示的时间线完全错乱。排查前最好确认监控服务器和应用服务器都同步了NTP别在这种基础问题上浪费半天时间。最后再分享一个实际体会排查接口变慢这件事做得多了会发现真正难的不是找到“哪里慢”而是别被表象带着走。我每次接到“接口变慢”的反馈都会强制自己按流程走先看分位数和影响范围再打开Trace找耗时大头接着按SQL、外部依赖、本地代码、基础设施的顺序逐层下钻最后验证修复效果。这一套流程走下来绝大多数问题都能在半小时内定位。还有一个很实用的小习惯在APM后台把每次故障的慢Trace链接和日志里的TraceID一起保存下来归档到团队的知识库里。下次再遇到类似的接口变慢直接搜历史记录往往能直接找到“上次也是这个问题”的结论省下的时间不比用APM本身少。排查工具是死的但排查方法是活的把这套流程沉淀成团队的共同经验才是应对线上接口变慢最稳的办法。
返回列表