周四上午，测试同学又来了：“商品详情接口偶发慢，大概一百次里有两三次，正好 3 秒。你看日志有啥没？”我看了日志：没有 ERROR，没有 WARN，慢请求的 Controller 日志间隔 3.01 秒，中间空空如也。我又看了 APM 的链路：耗时集中在 GoodsService.detail 里，没有下游 RPC，没有 SQL，3 秒像凭空消失了。
如果是在几年前，我会走三步：加日志、发版、等它再复现。加一次日志要走一轮发布流程，还得祈祷“偶发”这次别偷懒。现在我有 Arthas——一个可以在不重启、不改代码的前提下，往运行中的 JVM 里“打针抽血”的诊断工具。这篇就用它，把一个“偶发 3 秒”从发现走到定位，再走到临时止血。
一、现象：有规律的“偶发”，日志里查无此人
先整理已知信息，好的排查从收窄范围开始：
- 慢请求耗时几乎正好 3 秒（3.00–3.02 秒）。正好是整数秒，基本可以断定是某个超时时间被触发，而不是随机的慢；
- 发生概率约 2%~3%，说明有一个“每 N 次请求会走到一次”的分支，比如轮询、负载均衡、缓存过期；
- 所有实例都有，不是单机问题；
- 日志、慢 SQL、下游 RPC 均正常。
整数秒的慢 = 超时。这是第一条经验：看到规整的耗时（1s、3s、5s、30s），先想超时配置，再想别的。那么是哪个超时？谁在等？这就是 Arthas 出场的时候了。
二、排查路线图
三、动手：一步一步把 3 秒“抓出来”
第 1 步：attach 到目标 JVM
Arthas 官方快速入门的流程：下载 arthas-boot.jar，用与目标进程相同的用户运行，它会列出本机 Java 进程让你选择。生产上要注意：先在一台实例上做，并且确认公司的安全规范允许。
$ curl -O https://arthas.aliyun.com/arthas-boot.jar # 或者从内部制品库获取，生产机通常没有外网
$ java -jar arthas-boot.jar
* [1]: 4187 goods-service.jar
[2]: 5230 xxl-job-executor.jar
1
[INFO] arthas home: /home/app/.arthas/lib/3.7.2/arthas
[INFO] Try to attach process 4187
[INFO] Attach process 4187 success.
[INFO] arthas-client connect 127.0.0.1 3658
,---. ,------. ,--------.,--. ,--. ,---. ,---.
/ O \ | .--. ''--. .--'| '--' | / O \ ' .-'
...
wiki https://arthas.aliyun.com/doc
version 3.7.2
pid 4187
time 2026-09-24 10:21:33
[arthas@4187]$
Attach process success 后进入交互控制台。退出时有两个命令要分清（官方文档）：quit/exit 只是退出当前控制台，Arthas 仍在目标进程里跑；stop 才会彻底卸载，用完一定要 stop，别把诊断工具遗留在生产进程里。
第 2 步：dashboard 看全局，判断是“忙”还是“等”
[arthas@4187]$ dashboard -n 1
ID NAME GROUP PRIORITY STATE %CPU DELTA_TIME TIME INTERRUPTED DAEMON
-1 C2 CompilerThread0 - -1 - 0.9 0.001 0:12.4 false true
38 http-nio-8080-exec-6 main 5 RUNNABLE 0.4 0.000 0:03.1 false true
41 http-nio-8080-exec-9 main 5 WAITING 0.1 0.000 0:02.7 false true
...
Memory used total max usage GC
heap 812M 2048M 2048M 39.66% gc.g1_young_generation.count 212
g1_old_gen 561M 1600M 2048M 27.4% gc.g1_young_generation.time(ms) 4721
Runtime
os.name Linux java.version 1.8.0_342
processors 8 uptime 172800s
dashboard 一屏给出线程列表、内存与 GC 计数、运行时信息。这里的结论很快：堆使用率 40%、GC 次数平稳、没有线程 CPU 特别高——不是 GC，也不是 CPU 型问题，是“等”，和前面的“整数秒 = 超时”互相印证。-n 1 表示只刷新一次，不然它会一直刷屏。
第 3 步：thread 看谁在等，等在哪
Arthas 的 thread 命令在官方文档里的几个常用姿势：thread -n 3 按 CPU 占用率列出最忙的前 3 个线程并带栈；thread -b 找出阻塞了其他线程的那个线程（注意它只检测 synchronized 的锁竞争，不包括 java.util.concurrent 的锁）；thread --state WAITING 按状态过滤；thread <id> 看指定线程的栈。因为“偶发”，我们让它连续抓几次：
[arthas@4187]$ thread --state TIMED_WAITING | head -5
[arthas@4187]$ thread -b
No most blocking thread found! # 没有 synchronized 锁竞争，排除“锁导致的 3 秒”
[arthas@4187]$ thread 41
"http-nio-8080-exec-9" Id=41 RUNNABLE (in native)
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
...
at java.net.Socket.connect(Socket.java:589)
at org.apache.http.conn.socket.PlainConnectionSocketFactory.connectSocket(PlainConnectionSocketFactory.java:75)
...
at com.demo.goods.client.RuleClient.fetch(RuleClient.java:63)
at com.demo.goods.service.PromotionService.calc(PromotionService.java:88)
at com.demo.goods.service.GoodsService.detail(GoodsService.java:45)
这次运气不错，恰好抓到一个正在 socketConnect 的线程：它在建立 TCP 连接，调用链是 GoodsService.detail → PromotionService.calc → RuleClient.fetch。但“抓到一次”只是线索，不是证据——采样式的 thread 看的是瞬间，偶发问题不能靠运气。要拿证据，就用 trace：它会在方法被调用时统计每一层的耗时，并且可以用 #cost 条件只输出慢的那次。
第 4 步：trace 逐层下钻，用 #cost 过滤出慢请求
官方文档中 trace 的语法是 trace <class-pattern> <method-pattern> [condition-express]；-n 限制输出次数（默认 100），'#cost > 1000' 表示只在耗时超过 1000ms 时输出；每次 trace 只展开被追踪方法的第一层子调用，所以要一层一层往下追。
# 第 1 层：从入口开始，只看超过 1 秒的调用，最多抓 3 次
[arthas@4187]$ trace com.demo.goods.service.GoodsService detail '#cost > 1000' -n 3
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 214 ms, listenerId: 3
`---ts=2026-09-24 10:35:17;thread_name=http-nio-8080-exec-9;id=29;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@2f1c
`---[3012.5ms] com.demo.goods.service.GoodsService:detail()
+---[1.2ms] com.demo.goods.mapper.GoodsMapper:selectById() #41
+---[0.4ms] com.demo.goods.cache.LocalCache:get() #43
+---[3006.8ms] com.demo.goods.service.PromotionService:calc() #45
`---[0.9ms] com.demo.goods.service.GoodsService:assemble() #49
3012ms 里，PromotionService.calc 就占了 3006.8ms，其他都是毫秒级。范围从整个接口缩小到一个方法。再往下一层：
# 第 2 层：追 PromotionService.calc
[arthas@4187]$ trace com.demo.goods.service.PromotionService calc '#cost > 1000' -n 2
`---ts=2026-09-24 10:37:52;thread_name=http-nio-8080-exec-3;id=1d;is_daemon=true;priority=5;TCCL=...
`---[3008.1ms] com.demo.goods.service.PromotionService:calc()
+---[0.2ms] com.demo.goods.service.PromotionService:normalize() #86
+---[3006.9ms] com.demo.goods.client.RuleClient:fetch() #88
`---[0.6ms] com.demo.goods.service.PromotionService:apply() #90
# 第 3 层：追 RuleClient.fetch，用 --skipJDKMethod false 把 JDK 方法也展示出来
[arthas@4187]$ trace com.demo.goods.client.RuleClient fetch '#cost > 1000' --skipJDKMethod false -n 2
`---ts=2026-09-24 10:39:05;thread_name=http-nio-8080-exec-11;id=2b;is_daemon=true;priority=5;TCCL=...
`---[3005.7ms] com.demo.goods.client.RuleClient:fetch()
+---[0.1ms] java.util.List:size() #58
+---[0.05ms] java.util.concurrent.atomic.AtomicInteger:getAndIncrement() #59
+---[3004.9ms] org.apache.http.impl.client.CloseableHttpClient:execute() #63
`---[0.2ms] com.demo.goods.client.RuleClient:parse() #66
三层之后，慢点收敛到 CloseableHttpClient.execute() 的一次 HTTP 调用（3004.9ms），同时注意到它前面有一行 AtomicInteger.getAndIncrement()——像是一个轮询计数器：每次请求递增一次，选择一个服务节点。这与“每 N 次里有一次慢”的规律吻合。下一个问题：它请求的到底是哪个地址？为什么慢？这就是 watch 的用武之地。
第 5 步：watch 观察入参、返回值和异常
官方文档中 watch 的语法：watch <class-pattern> <method-pattern> <express> [condition]；表达式里可用 params（入参）、target（this 对象）、returnObj（返回值）、throwExp（异常）、#cost（耗时）；观察点 -b（调用前）、-s（成功返回）、-e（抛异常）、-f（结束时，默认）；-x 控制对象展开深度（默认 1）。先盯住慢的 HTTP 调用，看它的请求和异常：
[arthas@4187]$ watch org.apache.http.impl.client.CloseableHttpClient execute '{params[0], throwExp, #cost}' '#cost > 1000' -x 2 -n 3
Press Q or Ctrl+C to abort.
method=org.apache.http.impl.client.CloseableHttpClient.execute location=AtExceptionExit
ts=2026-09-24 10:41:18; [cost=3005.412ms] result=@ArrayList[
@HttpGet[GET http://10.20.30.42:8080/rules/promotion?sku=10086 HTTP/1.1],
@ConnectTimeoutException[org.apache.http.conn.ConnectTimeoutException: Connect to 10.20.30.42:8080 [/10.20.30.42] failed: connect timed out],
@Double[3005.412],
]
method=org.apache.http.impl.client.CloseableHttpClient.execute location=AtExceptionExit
ts=2026-09-24 10:41:44; [cost=3004.887ms] result=@ArrayList[
@HttpGet[GET http://10.20.30.42:8080/rules/promotion?sku=10087 HTTP/1.1],
@ConnectTimeoutException[...connect timed out],
...
证据到手：location=AtExceptionExit 说明这次调用是以异常结束的，异常是 ConnectTimeoutException ... connect timed out，目标是 10.20.30.42:8080，耗时 3005ms。连接一个不可达的节点，在 TCP 握手阶段等满了 3 秒的 connectTimeout。而请求最终之所以成功（用户看到的只是慢，没有报错），说明上层捕获了这个异常并做了降级或重试。再用 stack 看看这个调用点是谁触发的（官方文档：stack 输出方法被调用时的完整调用路径，也支持 #cost 条件）：
[arthas@4187]$ stack com.demo.goods.client.RuleClient fetch '#cost > 1000' -n 1
ts=2026-09-24 10:43:02;thread_name=http-nio-8080-exec-7;id=23;is_daemon=true;priority=5;TCCL=...
@com.demo.goods.client.RuleClient.fetch()
at com.demo.goods.service.PromotionService.calc(PromotionService.java:88)
at com.demo.goods.service.GoodsService.detail(GoodsService.java:45)
at com.demo.goods.web.GoodsController.detail(GoodsController.java:29)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
...
调用链明确：GoodsController.detail → GoodsService.detail → PromotionService.calc → RuleClient.fetch。接下来要回答“为什么会选到一个死节点”，就要看线上真实运行的代码。
第 6 步：jad 反编译线上代码，确认与源码一致
线上跑的字节码不一定等于你本地分支的代码（发错版本、热修补丁的情况都有）。jad 直接把 JVM 里已加载的类反编译出来，看到的是线上真相：
[arthas@4187]$ jad --source-only com.demo.goods.client.RuleClient fetch
public List<Rule> fetch(String path) {
int idx = Math.abs(this.counter.getAndIncrement() % this.nodes.size());
String node = this.nodes.get(idx); // 简单轮询选节点，没有健康检查、没有剔除
HttpGet get = new HttpGet("http://" + node + path);
try {
CloseableHttpResponse resp = this.client.execute((HttpUriRequest) get); // connectTimeout = 3000
return this.parse(resp);
} catch (IOException e) {
log.debug("fetch rule failed, node={}", node, e); // 只有 debug 日志！
return Collections.emptyList(); // 降级：返回空规则，用户看到“无优惠”
}
}
真相大白。再看一眼配置，确认 nodes 里到底有几个节点：
[arthas@4187]$ ognl -x 2 '@com.demo.goods.client.RuleClient@INSTANCE.nodes'
@ArrayList[
@String[10.20.30.41:8080],
@String[10.20.30.42:8080],
@String[10.20.30.43:8080],
@String[10.20.30.44:8080],
]
ognl 可以直接读取线上对象的静态字段或单例属性，很适合“核对配置到底是什么”，比翻配置中心快。4 个节点，其中 10.20.30.42 那台三天前下线了，但配置里忘了摘掉。
四、根因：轮询 + 死节点 + 3 秒连接超时 + 吞掉异常
把证据串起来，一张图讲完：
四个因素叠加：
- 配置里留着死节点：节点下线，但客户端的静态节点列表没同步；
- 简单轮询，没有健康检查/熔断/剔除：死节点每 4 次被选中 1 次；
- 连接超时 3 秒且在请求线程同步等待：对不可达的 IP，TCP SYN 得不到回应，客户端只能等到 connectTimeout；如果是“端口拒绝连接”（有机器但没进程），会瞬间失败，反而不慢——所以“慢”是“黑洞”，不是“拒绝”；
- 异常被吞掉，只打 debug：线上默认 info 级别，所以日志里“查无此人”。
五、止血与修复
止血：redefine 热修，不重启
先说明：热修是应急手段，不是发布流程的替代品，必须同时走正式修复。Arthas 的热更新流程官方文档写得很清楚：jad 导出源码 → 修改 → mc 内存编译 → redefine 加载。并且有明确限制：不能新增/删除字段和方法，也不能改方法签名；redefine 后无法还原；与 watch/trace/jad/monitor/tt 等增强命令有冲突（所以先 stop 或 reset 掉增强）；官方也推荐优先考虑 retransform。我们的临时修改很小：在 fetch 选节点后加一个判断，遇到已下线的 10.20.30.42:8080 就换下一个节点。只改方法体、不增不减字段与方法，符合限制（connectTimeout 在构造函数里已固化进 HttpClient，直接改常量无效，这也是热修前必须先读懂代码的原因）。
# 1) 先清掉之前的增强，避免与 redefine 冲突
[arthas@4187]$ reset
# 2) 反编译并保存源码，编辑：在 fetch 方法体开头加一行“跳过 10.20.30.42:8080 就重选下一个”的判断（只改方法体，不增字段）
[arthas@4187]$ jad --source-only com.demo.goods.client.RuleClient > /tmp/RuleClient.java
# 3) 内存编译（指定 classloader，避免找不到依赖）
[arthas@4187]$ classloader -t | head -3 # 找到 Spring Boot 的 classloader hash，例如 2f1c
[arthas@4187]$ mc -c 2f1c /tmp/RuleClient.java -d /tmp
Memory compiler output:
/tmp/com/demo/goods/client/RuleClient.class
Affect(row-cnt:1) cost in 1433 ms.
# 4) 热加载
[arthas@4187]$ redefine /tmp/com/demo/goods/client/RuleClient.class
redefine success, size: 1, classes:
com.demo.goods.client.RuleClient
再用 trace / 观察接口的 P99，3 秒的尖峰消失了。这里要强调一个纪律：redefine 只存在于这个 JVM 的内存里，重启即失效，且线上代码与 Git 仓库不再一致。所以热修之后，立刻做三件事：在工单里记录“已做热修 + 修改内容”；同时提交正式修复；下一次发版覆盖它。最后别忘了 stop 卸载 Arthas。
用 profiler 火焰图做“旁证”
为了确认没有别的隐藏耗时，热修前我们还用 Arthas 内置的 async-profiler 抓了一份 wall-clock 火焰图（cpu 事件只统计在 CPU 上的时间，而我们的问题是“线程在等”，所以要用 wall）。官方文档中的用法：profiler start 开始（默认 cpu），--event 指定事件类型（cpu、alloc、lock、wall 等），-d/--duration 自动停止，profiler stop 生成结果文件，默认是 HTML 火焰图，profiler status 查看状态：
[arthas@4187]$ profiler start --event wall -d 60
Started [wall] profiling
[arthas@4187]$ profiler status
[wall] profiling is running for 23 seconds
[arthas@4187]$ profiler stop --format html
OK
profiler output file: /home/app/arthas-output/20260924-104811.html
# 通过 Arthas 自带的 http 端口下载/查看（默认仅监听 127.0.0.1:3658，可用 ssh 端口转发）：
# http://127.0.0.1:3658/arthas-output/20260924-104811.html
火焰图怎么读：横轴是采样占比（越宽占用的墙钟时间越多），纵轴是调用栈深度（下面是调用者、上面是被调用者）。wall 模式下，那个 Socket.connect → PlainSocketImpl.socketConnect 的“塔”占了请求线程约 2.4% 的宽度，与我们的 2.5% 计算吻合，其余请求线程的时间大部分在 epoll_wait（空闲等待新请求，属于正常）。火焰图不是用来“发现”凶手的（trace 已经抓到了），而是用来确认“有没有第二个凶手”。火焰图文件不含业务数据，但仍含类名/方法名，别随手发到公网。
根治
// 1) 超时按“内网健康节点应有的时延”设置：连接 200~300ms，读 1s；借连接超时 200ms
RequestConfig rc = RequestConfig.custom()
.setConnectTimeout(300).setSocketTimeout(1000).setConnectionRequestTimeout(200).build();
// 2) 不要自己写轮询：接入注册中心（Nacos）+ 客户端负载均衡，自带健康检查和剔除
// 或至少做“失败摘除”：连续失败 N 次的节点熔断 30 秒
class Node { volatile long unhealthyUntil; }
private boolean available(Node n) { return System.currentTimeMillis() > n.unhealthyUntil; }
// 失败时：n.unhealthyUntil = System.currentTimeMillis() + 30_000;
// 3) 降级不能静默：异常至少 WARN，并且埋点计数，指标超阈值告警
} catch (IOException e) {
log.warn("fetch rule failed, node={}, cost={}ms", node, cost, e);
metrics.counter("rule.fetch.fail", "node", node).increment();
return Collections.emptyList();
}
同时把配置中心里的节点列表清理掉，并在下线流程里加一条 checklist：“下线节点前，确认无客户端静态引用”。修复发布后，观察一周，详情接口 P99 稳定在 80ms 以内，rule.fetch.fail 指标为 0。
在生产使用 Arthas 的几条纪律
- 先小后大：先在一台实例上操作，且优先用只读命令（dashboard、thread、jad、ognl）；
- 带条件、带次数：
trace/watch/stack一律加'#cost > N'和-n，否则高 QPS 方法的增强会带来明显开销与刷屏； - 用完清理：
reset还原增强的类，stop卸载 Arthas；官方文档提醒quit不会卸载它； - watch 表达式别有副作用：OGNL 表达式能调用方法，不要在生产 watch 里调用会修改状态的方法；
- 权限与合规：Arthas 能读取内存中的任意数据（包括用户信息），要遵循公司的生产变更与数据安全流程；HTTP 端口默认只监听本地，不要暴露到公网。
六、复盘：这类坑怎么提前躲开
| 做法 | 为什么 |
|---|---|
| 看到“整数秒”的慢，先怀疑超时配置 | 1s/3s/5s/30s 大概率是某个 timeout 被触发，而不是随机慢 |
| 排查顺序：dashboard 判断忙/等 → thread 看栈 → trace 逐层下钻 → watch 看数据 → stack 看调用者 | 每一步都缩小范围，不靠猜；trace 每次只展开一层，要逐层往下 |
trace/watch 使用 '#cost > N' 与 -n | 只抓慢的那几次，且控制对生产的影响 |
| 热修只用于止血，并立刻补正式修复；记录变更 | redefine 重启即失效，且改变了线上代码与仓库的一致性 |
| 吞异常必须留 WARN 日志与指标 | “降级”不能等于“静默”，否则问题会在日志里隐身 |
| 下游节点用注册中心 + 健康检查 + 熔断，不要手写静态轮询 | 节点下线、故障时能自动剔除，避免概率性慢请求 |
| 下线节点前检查静态引用（配置、白名单、hosts） | “忘记摘除”是最常见的死节点来源 |
一句话备忘：偶发慢先看耗时是否“整秒” →
dashboard分清忙与等 →trace 类 方法 '#cost>1000' -n 3逐层下钻 →watch看入参与异常 →stack看谁调的 →jad对线上代码 → 必要时mc + redefine热修 →profiler --event wall复核 → 用完stop。
复盘会上，运维同学听完摸了摸下巴：“所以，那台三天前下线的机器，为我们贡献了三天的 3 秒？”我说：“对，而且它下线得很安静，连遗言都没留。”后来，我们在下线流程里加了一条：机器走之前，先问问有没有人还惦记着它。
参考资料
- Arthas 官方文档：Quick Start——arthas-boot.jar 的 attach 流程、dashboard/thread/jad/watch 基本用法，以及 quit 与 stop 的区别。
- Arthas 官方文档：trace——追踪方法调用路径与各节点耗时、
#cost条件、-n、--skipJDKMethod，以及每次只展开第一层。 - Arthas 官方文档：watch——params/returnObj/throwExp/#cost 表达式变量，-b/-e/-s/-f 观察点，-x 展开深度。
- Arthas 官方文档：thread——
-n最忙线程、-b找阻塞线程（仅 synchronized）、--state过滤与 CPU 占用计算方式。 - Arthas 官方文档：stack——输出方法被调用的完整调用路径，并支持条件表达式与
-n。 - Arthas 官方文档：redefine——jad → mc → redefine 的热更新流程，以及不能增删字段/方法、不可恢复、与增强命令冲突等限制。
- Arthas 官方文档：profiler——start/stop/status、
--event（cpu/alloc/lock/wall 等）、-d自动停止与 HTML 火焰图输出。
一起聊聊