问题：一个只在生产出现的接口变慢
九月下旬，客服反馈"订单详情页打开很慢"。我在测试环境怎么点都是 80ms，生产上就是 3 秒左右。
按以前的办法，要么加日志重新发版（生产发一次要走流程，至少半小时），要么 jstack 抓线程栈（只能看某一瞬间的状态，看不到耗时分布）。这次我试了下 Arthas，20 分钟就定位到了，没重启也没发版。
装上
Arthas 3.3.9，直接用 arthas-boot：
$ curl -O https://arthas.aliyun.com/arthas-boot.jar
$ java -jar arthas-boot.jar
[INFO] arthas-boot version: 3.3.9
[INFO] Found existing java process, please choose one and hit RETURN.
* [1]: 12847 com.xxx.OrderApplication
[2]: 21033 org.apache.rocketmq.namesrv.NamesrvStartup
1
[INFO] arthas home: /root/.arthas/lib/3.3.9/arthas
[INFO] Try to attach process 12847
[INFO] Attach process 12847 success.
[INFO] arthas-client connect 127.0.0.1 3658
,---. ,------. ,--------.,--. ,--. ,---. ,---.
/ O \ | .--. ''--. .--'| '--' | / O \ ' .-'
| .-. || '--'.' | | | .--. || .-. |`. `-.
| | | || |\ \ | | | | | || | | |.-' |
`--' `--'`--' '--' `--' `--' `--'`--' `--'`-----'
原理是 JVM 的 attach 机制（VirtualMachine.attach），通过一个 agent 注入到目标进程。所以要求执行 arthas 的用户和 JVM 进程是同一个用户。我们容器里都是 root，直接能连。
dashboard：先看整体
$ dashboard
一个实时刷新的面板，分三块：线程（按 CPU 占用排序）、内存（各区使用率 + GC 次数耗时）、运行时信息（JDK 版本、启动参数）。
ID NAME GROUP PRIORITY STATE %CPU DELTA_TIME TIME INTERRUPTED DAEMON
32 http-nio-8080-exec-15 main 5 RUNNABL 68.24 0.136 0:42 false true
28 http-nio-8080-exec-11 main 5 RUNNABL 12.31 0.024 0:15 false true
-1 C2 CompilerThread0 - -1 - 5.22 0.010 0:31 false true
Memory used total max usage GC
heap 3821M 4096M 4096M 93.27% gc.ps_scavenge.count 1241
ps_eden_space 892M 1024M 1024M 87.15% gc.ps_scavenge.time(ms) 18422
ps_survivor_space 40M 64M 64M 63.11% gc.ps_marksweep.count 12
ps_old_gen 2888M 3008M 3008M 96.02% gc.ps_marksweep.time(ms) 8412
Runtime
os.name Linux
java.version 1.8.0_241
老年代 96%，Full GC 12 次共 8.4 秒——堆有问题。同时 http-nio-8080-exec-15 这个线程 CPU 68%，明显在干活。按 q 退出（或者 Ctrl+C）。
注意：dashboard 别一直开着，它自己也有开销（要采集所有线程的信息）。看几眼就够了。
trace：定位慢在哪一层
知道接口慢，但不知道慢在调用链的哪一环。trace 命令能输出方法内部调用的耗时树。先找到类的全限定名：
$ sc *OrderController*
com.xxx.controller.OrderController
Affect(row-cnt:1) cost in 22 ms.
然后 trace 它的方法：
$ trace com.xxx.controller.OrderController detail '#cost > 500'
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 132 ms.
`---ts=2020-09-26 15:42:11;thread_name=http-nio-8080-exec-15;id=1f;is_daemon=true;priority=5;
`---[3128.442ms] com.xxx.controller.OrderController:detail()
+---[0.042ms] com.xxx.controller.OrderController:getUserId()
+---[2841.331ms] com.xxx.service.OrderService:getDetail() # 慢在这一层
`---[0.031ms] com.xxx.vo.Result:success()
'#cost > 500' 是条件表达式，只输出耗时超过 500ms 的调用，避免被正常请求刷屏。这个表达式语法是ognl 的，能访问方法参数（params[0]）、返回值、异常等。
继续往下挖一层：
$ trace com.xxx.service.OrderService getDetail '#cost > 500'
`---[2841.331ms] com.xxx.service.OrderService:getDetail()
+---[0.882ms] com.xxx.mapper.OrderMapper:selectById()
+---[12.412ms] com.xxx.client.UserClient:getUser()
+---[2812.774ms] com.xxx.service.CouponService:listByOrder() # 就是它
`---[3.112ms] com.xxx.service.LogisticsService:getStatus()
$ trace com.xxx.service.CouponService listByOrder '#cost > 500'
`---[2812.774ms] com.xxx.service.CouponService:listByOrder()
+---[0.221ms] org.springframework.web.client.RestTemplate:exchange()
+---[2809.112ms] com.xxx.util.CouponFilter:match() # 纯 CPU 计算
`---[0.114ms] java.util.stream.Collectors:toList()
找到了。CouponFilter.match() 是个纯内存计算的方法，跑了 2.8 秒。
watch：看看它到底在算什么
watch 能看方法的入参、返回值、异常。先看看入参规模：
$ watch com.xxx.util.CouponFilter match '{params[0].size(), params[1].size()}' -x 2
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 88 ms.
ts=2020-09-26 15:47:22; [cost=2809.44ms] result=ArrayList[
@Integer[12], # params[0] 只有 12 个元素
@Integer[84312], # params[1] 有 84312 个元素
]
-x 2 是展开层级，默认 1 层看不清内容。{params[0].size(), params[1].size()} 是观察表达式，直接调用了参数对象的方法。
12 × 84312 = 101 万次比较，不该要 2.8 秒。看来是嵌套循环里做了什么重活。看看方法体：
$ jad com.xxx.util.CouponFilter
jad：反编译确认线上代码
jad 把 JVM 里实际加载的字节码反编译成 Java 源码。这个非常重要——它反编译的是运行中的类，不是你本地的代码，能确认线上跑的到底是哪一版。
$ jad com.xxx.util.CouponFilter match
ClassLoader:
+-org.springframework.boot.loader.LaunchedURLClassLoader@3fee733d
Location:
/BOOT-INF/classes/
public List<Coupon> match(List<Coupon> coupons, List<OrderItem> items) {
List<Coupon> result = new ArrayList<Coupon>();
for (Coupon coupon : coupons) {
for (OrderItem item : items) {
// 每次都去查一次商品类目树
Category category = categoryMapper.selectById(item.getCategoryId());
if (coupon.getCategoryIds().contains(category.getId())) {
result.add(coupon);
}
}
}
return result;
}
循环里套了个数据库查询。101 万次 selectById，每次 2.8 微秒，就是 2.8 秒。categoryMapper.selectById 有 MyBatis 一级缓存，但只在同一个 SqlSession 内有效，这里是 Spring 管理的，每次调用都是新查询。
我当时看到这段代码的第一反应是"这不可能是我写的"，jad 之后确认了 ClassLoader 和 Location，确实是 /BOOT-INF/classes/ 里跑的这一版。后来翻 git log 才发现是两个月前一次重构时，有人把外面的预加载挪进了循环。
验证一下：ognl 直接调方法
在改代码之前，我想先验证一下"把类目查询挪到循环外"能快多少。Arthas 的 ognl 命令可以直接执行表达式，甚至调用 Spring 容器里的 bean：
# 先拿到 Spring 的 ApplicationContext
$ tt -t com.xxx.controller.OrderController detail -n 1 # 记录一次调用
更简单的办法是用 vmtool（3.5+ 才有，3.3.9 没有）。我用了一个土办法——写个临时的单元测试在本地验证，改完之后耗时从 2809ms 降到 6ms。生产上先用热更新顶一下。
热更新（jad + mc + redefine）
这是 Arthas 最有名也最危险的功能。流程是三步：反编译 → 改代码 → 重新编译并加载。
# 1. 反编译到文件
$ jad --source-only com.xxx.util.CouponFilter > /tmp/CouponFilter.java
# 2. 改 /tmp/CouponFilter.java，把查询挪到循环外
改完之后的方法：
public List<Coupon> match(List<Coupon> coupons, List<OrderItem> items) {
// 先把需要的类目一次性查出来
Set<Long> categoryIds = items.stream()
.map(OrderItem::getCategoryId)
.collect(Collectors.toSet());
Map<Long, Category> categoryMap = categoryMapper.selectBatchIds(categoryIds)
.stream()
.collect(Collectors.toMap(Category::getId, c -> c));
List<Coupon> result = new ArrayList<Coupon>();
for (Coupon coupon : coupons) {
for (OrderItem item : items) {
Category category = categoryMap.get(item.getCategoryId());
if (category != null && coupon.getCategoryIds().contains(category.getId())) {
result.add(coupon);
}
}
}
return result;
}
# 3. 用 MemoryCompiler 编译
$ mc /tmp/CouponFilter.java -d /tmp
Memory compiler output:
/tmp/com/xxx/util/CouponFilter.class
Affect(row-cnt:1) cost in 3421 ms.
# 4. 加载进 JVM
$ redefine /tmp/com/xxx/util/CouponFilter.class
redefine success, size: 1, classes:
com.xxx.util.CouponFilter
再 trace 一次，接口从 3128ms 降到 62ms。
redefine 的几条规定必须知道：
- 不能修改方法签名（增删改方法、改参数），只能改方法体。
- 不能新增字段，改了字段会失败。
- 正在执行的方法不会被替换，新的调用才生效。
- redefine 之后再用 jad 反编译，看到的是修改后的代码，但 class 文件在磁盘上没变。JVM 重启就恢复原样。所以它只是临时救急，真正的修复必须改代码发版。
我们当天晚上就走了正常发版流程把代码合进去了，热更新只是用来止血和验证思路。
顺手把堆的问题也看了
回到开头 dashboard 里老年代 96% 的问题。用 heapdump 导出一份：
$ heapdump /tmp/order.hprof
Dumping heap to /tmp/order.hprof...
Heap dump file created
1.2GB 的文件，用 sz 拉到本地（或者用 heapdump --live 只 dump 存活对象，文件小一些）。MAT 打开，Leak Suspects 报告：
Problem Suspect 1
1,842,331 instances of "com.xxx.vo.OrderItemVO", loaded by
"org.springframework.boot.loader.LaunchedURLClassLoader @ 0x6c0312345" occupy 1,882,441,208 (77.31%) bytes.
Keywords: com.xxx.vo.OrderItemVO
184 万个 OrderItemVO 占了 1.88GB。追引用链（Path to GC Roots）找到一个 Guava Cache：
@Bean
public Cache<Long, List<OrderItemVO>> orderItemCache() {
return CacheBuilder.newBuilder()
.maximumSize(100000)
.expireAfterWrite(30, TimeUnit.MINUTES)
.build();
}
每个 List 平均 18 个元素，10 万条就是 184 万个对象。maximumSize 限制的是条目数不是对象数。这个缓存是另一个同事加的，本意是缓存订单明细，但没想到单个 VO 有 1KB。后来把 maximumSize 降到 5000，并且只缓存 id 列表。老年代稳定在 45%，Full GC 消失。
常用命令清单
整理一下我用得最多的几个：
| 命令 | 用途 | 示例 |
|---|---|---|
| dashboard | 整体面板 | dashboard -i 2000（2 秒刷新） |
| thread | 线程栈 | thread -n 3（CPU top3）、thread -b（找死锁） |
| trace | 方法调用链耗时 | trace com.x.A method '#cost>500' |
| watch | 看入参/返回值/异常 | watch com.x.A m '{params,returnObj}' -x 3 |
| jad | 反编译 | jad --source-only com.x.A |
| sc / sm | 查类 / 查方法 | sc -d *Service* |
| monitor | 方法调用统计 | monitor -c 5 com.x.A m（每 5 秒） |
| tt | 时空隧道，记录调用 | tt -t com.x.A m，tt -i 1000 -p 重放 |
| ognl | 执行表达式 | ognl '@com.x.A@staticField' |
| heapdump | 导堆 | heapdump --live /tmp/a.hprof |
几个我用下来觉得很有用的技巧：
trace一定要加'#cost > N'，否则生产上的正常请求会把输出刷爆。- trace 默认不显示 JDK 自带的方法调用，加
--skipJDKMethod false可以看到 JDK 方法的耗时。 watch的-x参数控制展开层级，看复杂对象要设到 3 或 4。- trace 对性能有影响。它在每个方法调用点都插入了埋点，实测让接口耗时增加 15~25%。定位完记得
stop关掉，或者reset清掉所有增强。
$ reset # 清除所有增强（trace/watch/tt 等都清掉）
$ stop # 关闭 arthas 服务端，退出
退出的时候一定要 stop，不要直接 kill 客户端。stop 会执行 reset，把字节码还原。如果直接杀进程，增强的字节码可能残留在 JVM 里。
小结
- Arthas 靠 attach 机制注入 agent，不需要重启应用，但要求同用户执行。
- 定位慢接口的标准流程：dashboard 看整体 → trace 找慢的调用层 → watch 看参数规模 → jad 确认线上代码。
- trace 有 15~25% 的性能开销，用完
reset，退出用stop。 - 热更新（jad + mc + redefine）只能改方法体，不能改签名和字段，重启失效。它是止血手段，不是修复手段。
- 最大的价值不是命令本身，而是不用发版就能看到生产环境正在跑什么。那次
jad出来发现线上代码和我本地不一样，比找到慢在哪更让我后背发凉。