现象：一个接口慢，但监控上看不出慢在哪
客服反馈"订单详情页打开要转好几秒"，我们查 Grafana，GET /order/{id}/detail 的 P99 从平时的 120 ms 涨到了 900 ms 左右，P50 没变。也就是说不是全量慢，是部分订单慢。
SkyWalking 8.6 上只能看到这个接口总共 900 ms，其中 MySQL 查询 40 ms、Redis 5 ms，剩下 855 ms 全是"应用自己耗掉的"，没有更细的埋点。那段代码是两年前写的，中间调了七八个方法，没有任何一行计时日志。
加日志重新发布？走发布流程至少半小时，而且这种"部分数据慢"的问题，加了日志也不一定抓得到。直接上 Arthas。
trace：把耗时摊到每一行
# 登上目标机器，容器里没装的话直接下
$ curl -O https://arthas.aliyun.com/arthas-boot.jar
$ java -jar arthas-boot.jar
[INFO] arthas-boot version: 3.5.4
[INFO] Found existing java process, please choose one and input the serial number of the process.
* [1]: 1 com.xxx.order.OrderApplication
1
先用 trace 抓超过 200 ms 的调用，抓 5 次就停：
$ trace com.xxx.order.controller.OrderController detail '#cost > 200' -n 5
等了几秒，抓到了：
---ts=2021-06-30 15:12:33;thread_name=http-nio-8080-exec-18;id=5b;is_daemon=true;priority=5;
---[823.4408ms] com.xxx.order.controller.OrderController:detail()
+---[0.0382ms] com.xxx.order.controller.OrderController:getLoginUser()
+---[41.2214ms] com.xxx.order.service.OrderService:getById()
+---[780.9163ms] com.xxx.order.service.OrderAssembler:buildDetailVO() ← 就是它
`---[0.9021ms] com.xxx.order.service.OrderService:logView()
buildDetailVO 占了 780 ms。继续往下钻：
$ trace com.xxx.order.service.OrderAssembler buildDetailVO '#cost > 200' -n 5
---[780.9163ms] com.xxx.order.service.OrderAssembler:buildDetailVO()
+---[12.4412ms] com.xxx.order.service.OrderAssembler:fillBuyerInfo()
+---[705.3387ms] com.xxx.order.service.OrderAssembler:fillItemSpec()
`---[61.9024ms] com.xxx.order.service.OrderAssembler:fillLogistics()
再往下，trace 一次只能跟一层，所以直接对最底层的方法 trace。这里有个坑：trace 默认会跳过 JDK 自带的方法调用，如果要看 List.stream() 这类，得加参数：
$ trace com.xxx.order.service.OrderAssembler fillItemSpec '#cost > 200' -n 5 --skipJDKMethod false
---[705.3387ms] com.xxx.order.service.OrderAssembler:fillItemSpec()
+---[703.1125ms] java.util.stream.ReferencePipeline:collect()
这下明白了：fillItemSpec 里有个 stream，每次循环都会调一次数据库（或者远程）查规格字典，循环了 47 次，每次 15 ms，累加 705 ms。订单商品条数越多越慢，这解释了为什么 P50 正常——大部分订单只有 2、3 个商品。
看源码确认（jad 直接反编译，不用去找代码仓库）：
$ jad --source-only com.xxx.order.service.OrderAssembler fillItemSpec
private List<ItemSpecVO> fillItemSpec(List<OrderItem> items) {
return items.stream().map(item -> {
// 每条商品查一次字典表，N+1
SpecDict dict = specDictMapper.selectById(item.getSpecId());
return ItemSpecVO.of(item, dict);
}).collect(Collectors.toList());
}
watch：确认入参和返回值
定位到了，但我还想知道传入的 items 到底多大、返回的 dict 有没有 null，免得改错方向：
$ watch com.xxx.order.service.OrderAssembler fillItemSpec \
'{params[0].size(), returnObj}' '#cost > 200' -x 2
输出：
method=com.xxx.order.service.OrderAssembler.fillItemSpec location=AtExit
ts=2021-06-30 15:14:07; [cost=712.3391ms] result=ArrayList[size=2]
@Integer[47]
@ArrayList[size=47]
确认了：47 个商品，返回 47 个 VO。-x 2 是展开层级，默认 1，对象深了会显示成 @Object[size=47] 看不见内容，一般给 3 就够。
watch 还有几个常用的开关：
# 只看方法进入时的入参（location=AtEnter），-b
$ watch com.xxx.order.service.OrderService getById '{params, target}' -b -x 3
# 只在抛异常时打印，抓偶发异常很好用
$ watch com.xxx.order.service.PayService pay '{params, throwExp}' -e -x 3
# 同时看入参、返回、异常
$ watch com.xxx.order.service.PayService pay '{params, returnObj, throwExp}' -x 3
表达式里能用的变量：params（数组）、target（this）、returnObj、throwExp、isReturn、isThrow、#cost。用 target 还能直接读实例字段，比如 target.specDictMapper。
热修复：jad + mc + redefine
问题清楚了，修复方案是批量查一次字典再 map。但线上已经在慢，走发布流程要半小时，我先用热更新顶一下。
第一步，把源码拉到本地改：
$ jad --source-only com.xxx.order.service.OrderAssembler > /tmp/OrderAssembler.java
改掉那段逻辑：
private List<ItemSpecVO> fillItemSpec(List<OrderItem> items) {
Set<Long> specIds = items.stream().map(OrderItem::getSpecId).collect(Collectors.toSet());
Map<Long, SpecDict> dictMap = specDictMapper.selectBatchIds(specIds)
.stream().collect(Collectors.toMap(SpecDict::getId, d -> d));
return items.stream()
.map(item -> ItemSpecVO.of(item, dictMap.get(item.getSpecId())))
.collect(Collectors.toList());
}
第二步，内存编译。这里有个必踩的坑：必须指定类加载器的 hash，否则会 ClassNotFoundException。用 sc 查：
$ sc -d com.xxx.order.service.OrderAssembler | grep classLoaderHash
classLoaderHash 6bc168d5
$ mc -c 6bc168d5 /tmp/OrderAssembler.java -d /tmp
Memory compiler output:
/tmp/com/xxx/order/service/OrderAssembler.class
第三步，热替换：
$ redefine /tmp/com/xxx/order/service/OrderAssembler.class
redefine success, size: 1, classes:
com.xxx.order.service.OrderAssembler
立刻再 trace 一次，fillItemSpec 从 705 ms 降到 8.3 ms，接口 P99 从 900 ms 掉回 130 ms。Grafana 上那根柱子十秒内就下来了。
热更新的几个限制
这套操作很爽，但限制不少，我在别的场景上吃过亏：
- 不能改方法签名、不能增删字段和方法，只能改方法体。想加字段就得老老实实发版。
- 正在执行的方法不会被替换，新请求才生效。
- redefine 之后原来增强过的类会失效。也就是说你之前
trace/watch的类，热更完得重新 trace 一遍。 - 热更完记得
reset，增强是有性能开销的（Arthas 用的是 ASM 字节码增强，每次调用都会有额外判断）：
$ reset com.xxx.order.service.OrderAssembler
$ quit
另外 mc 在有些 JDK 版本上编译会失败（找不到 tools.jar，JDK 9 之后被移除了），Arthas 3.5.x 在 JDK 11 上一般没问题，真不行就在本地 IDE 编译好 class 传上去，直接 redefine。
另外三个用得多的命令
tt（TimeTunnel）是我后来越用越多的。它能把一次方法调用的入参、返回值、异常完整录下来，事后反复回放，不用重新触发请求：
# 录下最近 100 次调用
$ tt -t com.xxx.order.service.OrderService getById -n 100
INDEX TIMESTAMP COST(ms) IS-RET IS-EXP OBJECT CLASS METHOD
1000 2021-06-30 15:22 712.33 true false 0x4a2b1c OrderService getById
1001 2021-06-30 15:22 18.42 true false 0x4a2b1c OrderService getById
# 看某一次的详细内容
$ tt -i 1000
# 甚至可以对这条记录重新发起调用（会真的再执行一次方法！）
$ tt -i 1000 -p
-p 是重放，会真的再跑一次方法。生产环境用之前要想清楚副作用，我一般只在查询类方法上用。
stack 用来回答"这个方法到底是谁调的"。有次一个 update 被调用得特别频繁，但代码里有七八处引用，静态看根本不知道哪些是热的：
$ stack com.xxx.order.service.OrderService update 'params[0] != null' -n 20
输出把每次调用的完整调用栈都打出来，统计一下就知道哪个入口占大头。
profiler 直接生成火焰图。Arthas 3.5 内置了 async-profiler：
# 采样 60 秒 CPU，生成火焰图
$ profiler start --event cpu --interval 1000000
$ profiler stop --format svg --file /tmp/cpu.svg
# 也可以采样内存分配
$ profiler start --event alloc
生成的是 SVG，下载到本地用浏览器打开就能交互查看。比起在机器上 top -Hp + jstack 猜，火焰图找热点快一个数量级。注意采样期间会有 5% 左右的性能损耗，别在流量高峰长时间开着。
顺带说一个我一直提醒自己的事：排查完一定要 reset。Arthas 的增强是在运行时改字节码，忘了 reset 就把进程留在一个被改过的状态里，我们有一次忘了，两天后另一个同事排查时被莫名其妙的栈搞晕了半天。
就写到这。如果哪天你也被《Arthas 高级用法：trace 定位慢方法与热更新》里同一个坑绊住，回来翻这篇，能省半小时。