本文介绍几个非常有用的 Arthas 命令,熟练使用这几个命令,可以让我们在排查线上问题的时候更加轻松。
关于 Arthas 的设计思想,美团技术团队的文章Java 动态追踪技术探究 一文中做了详细的说明,有兴趣可以去阅读一下。
trace trace
命令见名知意,可以用于跟踪方法内部的调用路径,渲染整个调用链路上所有的性能开销和跟踪调用链路。
例如,我们提供了一个 controller
,用来保存一笔订单数据,如下:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 package com.goku.order.rest;import com.goku.order.entity.Order;import lombok.extern.slf4j.Slf4j;import org.springframework.web.bind.annotation.PostMapping;import org.springframework.web.bind.annotation.RequestBody;import org.springframework.web.bind.annotation.RequestMapping;import org.springframework.web.bind.annotation.RestController;import java.util.*;@RestController @RequestMapping("/api/orders") @Slf4j public class OrderRestController { private static Random random = new Random (); @PostMapping public Map<String, Object> save (@RequestBody Order order) { long id = random.nextLong(); order.setId(id); Date now = new Date (); if (Objects.nonNull(order.getFlag()) && order.getFlag()) { log.info("调用路径1" ); } else { log.warn("调用路径2" ); } order.setCreateTime(now); order.setUpdateTime(now); log.info("request body : {}" , order); Map<String, Object> map = new HashMap <>(16 ); map.put("order" , order); return map; } }
现在项目在运行中,我们要查看 save
方法的链路,打开 arthas
并选择我们的工程,使用 trace com.goku.order.rest.OrderRestController save
命令并触发一次调用
1 2 3 4 5 6 7 8 9 Affect(class-cnt:1 , method-cnt:1) cost in 69 ms. `---ts=2020-01-18 22:40:56;thread_name=http-nio-8081-exec-1;id=14;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@4f824872 `---[3.6313ms] com.goku.order.rest.OrderRestController:save() +---[0.0164ms] com.goku.order.entity.Order:setId() #26 +---[0.0047ms] com.goku.order.entity.Order:getFlag() #28 +---[0.1695ms] org.slf4j.Logger:warn() #31 +---[0.0103ms] com.goku.order.entity.Order:setCreateTime() #33 +---[0.0062ms] com.goku.order.entity.Order:setUpdateTime() #34 `---[2.6388ms] org.slf4j.Logger:info() #35
从输出上来看,我们可以很清楚看到代码的 26、28、31、33、34、35 行被执行了,同样的,如果 order
对象的 flag
属性如果为 true,则第 31 行的调用会变成第 29 行,如下:
1 2 3 4 5 6 7 8 `---ts=2020-01-18 22:56:00;thread_name=http-nio-8081-exec-4;id=17;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@4f824872 `---[2.1072ms] com.goku.order.rest.OrderRestController:save() +---[0.0051ms] com.goku.order.entity.Order:setId() #26 +---[min=0.0023ms,max=0.0023ms,total=0.0046ms,count=2] com.goku.order.entity.Order:getFlag() #28 +---[0.6911ms] org.slf4j.Logger:info() #29 +---[0.0186ms] com.goku.order.entity.Order:setCreateTime() #33 +---[0.0032ms] com.goku.order.entity.Order:setUpdateTime() #34 `---[0.312ms] org.slf4j.Logger:info() #35