阿里Arthas(阿尔赛斯)-trace查看方法内部调用路径及耗时

关注

原创 2022-05-15 18:12:23 5.5k 阅读 AI 写同款· GEO 优化 ›

java-使用Arthas全链路统计方法调用链和执行耗时 Arthas监控诊断产品功能比较多，可以帮助我们不停服务在线诊断问题。使用jmh配合Arthas可以进行吞吐量、平均执行时间等基础测试和性能监控分析，帮助开发人员科学定位性能瓶颈和优化点。阅读详情

1.trace用法

参数名称参数说明
class-pattern 类名表达式匹配
method-pattern 方法名表达式匹配
condition-express 条件表达式
[E] 开启正则表达式匹配，默认为通配符匹配
[n:] 命令执行次数
#cost 方法执行耗时

2.方法内部调用路径，并输出方法路径上的每个节点上耗时

2.1追踪测试controller

[arthas@243829]$ trace com.ztesoft.bss.smart.controller.smartview.InjectionLabelSvController selectInjectionLabelByQo
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 738 ms, listenerId: 1
`---ts=2022-05-15 17:52:14;thread_name=http-nio-9283-exec-6;id=7e;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@388c519
`---[407.911209ms] com.ztesoft.bss.smart.controller.smartview.InjectionLabelSvController:selectInjectionLabelByQo()
`---[99.77% 406.961126ms ] com.ztesoft.bss.smart.service.smartview.InjectionLabelSvService:selectInjectionLabelByQo() #46

2.2调用service继续追踪

[arthas@243829]$ trace com.ztesoft.bss.smart.service.knowledge.InjectionLabelService selectInjectionLabelByQo
Press Q or Ctrl+C to abort.
Affect(class count: 4 , method count: 3) cost in 749 ms, listenerId: 2
`---ts=2022-05-15 17:53:12;thread_name=http-nio-9283-exec-4;id=7c;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@388c519
`---[42.843392ms] com.ztesoft.bss.smart.service.smartview.InjectionLabelSvService$$EnhancerBySpringCGLIB$$f8b2271c:selectInjectionLabelByQo()
`---[99.80% 42.758581ms ] org.springframework.cglib.proxy.MethodInterceptor:intercept()
`---[99.26% 42.442896ms ] com.ztesoft.bss.smart.service.knowledge.InjectionLabelService:selectInjectionLabelByQo()
+---[0.06% 0.024413ms ] com.ztesoft.bss.smart.qo.knowledge.InjectionLabelQo:getPage() #112
+---[0.02% 0.007316ms ] com.ztesoft.bss.smart.qo.knowledge.InjectionLabelQo:getRowNum() #113
+---[0.22% 0.093465ms ] com.ztesoft.sy.auth.account.AccountUtil:superAdminFlag() #115
+---[1.79% 0.760542ms ] com.ztesoft.sy.auth.account.AccountUtil:getComAcctId() #119
+---[0.03% 0.010955ms ] com.ztesoft.bss.smart.qo.knowledge.InjectionLabelQo:setComAcctId() #119
+---[0.02% 0.007334ms ] com.ztesoft.bss.smart.qo.knowledge.InjectionLabelQo:setCreateStaff() #120
+---[0.70% 0.298646ms ] com.ztesoft.bss.smart.service.sys.StaticDataService:getDcSystemParamByCache() #122
+---[86.32% 36.638723ms ] com.ztesoft.bss.smart.service.knowledge.InjectionLabelService:getInjectionLabelVoListByDataMarket() #126
+---[0.16% min=0.004865ms,max=0.013961ms,total=0.067991ms,count=10] com.ztesoft.bss.smart.vo.knowledge.InjectionLabelVo:getCreateStaff() #130
+---[7.39% min=0.191947ms,max=1.050793ms,total=3.136803ms,count=10] com.ztesoft.bss.smart.util.UserRedisUtil:getPortalUserInfoByUserId() #130
+---[0.16% min=0.00613ms,max=0.011424ms,total=0.069345ms,count=10] com.ztesoft.bss.smart.entity.redis.PortalUserInfo:getUserCode() #132
+---[0.15% min=0.005232ms,max=0.009599ms,total=0.061828ms,count=10] com.ztesoft.bss.smart.vo.knowledge.InjectionLabelVo:setStaffName() #132
+---[0.04% 0.017747ms ] com.github.pagehelper.PageInfo:<init>() #141
`---[0.04% 0.016784ms ] com.ztesoft.bss.smart.util.SmartPageHelper:toPageVO() #141

结果里的 #46，表示在run函数里，在源文件的第46行调用了selectInjectionLabelByQo()函数。

2.3追踪跳过jdk方法

[arthas@243829]$ trace --skipJDKMethod false com.ztesoft.bss.smart.controller.smartview.InjectionLabelSvController selectInjectionLabelByQo
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 250 ms, listenerId: 3
`---ts=2022-05-15 18:04:14;thread_name=http-nio-9283-exec-3;id=7b;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@388c519
`---[41.388497ms] com.ztesoft.bss.smart.controller.smartview.InjectionLabelSvController:selectInjectionLabelByQo()
`---[99.66% 41.248976ms ] com.ztesoft.bss.smart.service.smartview.InjectionLabelSvService:selectInjectionLabelByQo() #46

2.4根据耗时过滤

[arthas@243829]$ trace com.ztesoft.bss.smart.service.knowledge.InjectionLabelService selectInjectionLabelByQo '#cost > 10'
Press Q or Ctrl+C to abort.
Affect(class count: 4 , method count: 3) cost in 655 ms, listenerId: 5
`---ts=2022-05-15 18:06:46;thread_name=http-nio-9283-exec-10;id=82;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@388c519
`---[37.235754ms] com.ztesoft.bss.smart.service.smartview.InjectionLabelSvService$$EnhancerBySpringCGLIB$$f8b2271c:selectInjectionLabelByQo()
`---[99.56% 37.070939ms ] org.springframework.cglib.proxy.MethodInterceptor:intercept()
`---[98.81% 36.629713ms ] com.ztesoft.bss.smart.service.knowledge.InjectionLabelService:selectInjectionLabelByQo()
+---[0.06% 0.02256ms ] com.ztesoft.bss.smart.qo.knowledge.InjectionLabelQo:getPage() #112
+---[0.02% 0.005655ms ] com.ztesoft.bss.smart.qo.knowledge.InjectionLabelQo:getRowNum() #113
+---[0.25% 0.089755ms ] com.ztesoft.sy.auth.account.AccountUtil:superAdminFlag() #115
+---[1.97% 0.721886ms ] com.ztesoft.sy.auth.account.AccountUtil:getComAcctId() #119
+---[0.02% 0.008909ms ] com.ztesoft.bss.smart.qo.knowledge.InjectionLabelQo:setComAcctId() #119
+---[0.01% 0.005292ms ] com.ztesoft.bss.smart.qo.knowledge.InjectionLabelQo:setCreateStaff() #120
+---[0.75% 0.27514ms ] com.ztesoft.bss.smart.service.sys.StaticDataService:getDcSystemParamByCache() #122
+---[75.22% 27.553217ms ] com.ztesoft.bss.smart.service.knowledge.InjectionLabelService:getInjectionLabelVoListByDataMarket() #126
+---[0.80% min=0.003084ms,max=0.216341ms,total=0.294483ms,count=10] com.ztesoft.bss.smart.vo.knowledge.InjectionLabelVo:getCreateStaff() #130
+---[15.60% min=0.150012ms,max=1.987379ms,total=5.712897ms,count=10] com.ztesoft.bss.smart.util.UserRedisUtil:getPortalUserInfoByUserId() #130
+---[0.25% min=0.003333ms,max=0.018778ms,total=0.090289ms,count=10] com.ztesoft.bss.smart.entity.redis.PortalUserInfo:getUserCode() #132
+---[0.20% min=0.003077ms,max=0.018022ms,total=0.073496ms,count=10] com.ztesoft.bss.smart.vo.knowledge.InjectionLabelVo:setStaffName() #132
+---[0.11% 0.041464ms ] com.github.pagehelper.PageInfo:<init>() #141
`---[0.13% 0.047302ms ] com.ztesoft.bss.smart.util.SmartPageHelper:toPageVO() #141