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

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