项目场景
在生产环境,经常会遇到需要排查一个接口里哪里比较耗时,按照以前的做法,可能是通过打印logger,然后打补丁,重新部署
@Test
void testNeedTime() {
long startTime = System.currentTimeMillis();
AtomicInteger num1 = new AtomicInteger(1);
IntStream.range(1,10).forEach(i-> num1.incrementAndGet());
long endTime1 = System.currentTimeMillis();
log.info("耗时: {}" , endTime1 - startTime);
AtomicInteger num2 = new AtomicInteger(1);
IntStream.range(1,100).forEach(i-> num2.incrementAndGet());
long endTime2 = System.currentTimeMillis();
log.info("耗时: {}" , endTime2 - endTime1 );
}
如果是可以频繁更新的项目,或者是构建比较容易的项目,倒还好,如果项目不能频繁更新或者是部署过程比较麻烦,通过打补丁的方式就有点麻烦了,所以需要有款平台可以支持不打补丁就可以定时问题的分析工具,阿里开源的Arthas就是一款很不错的线上问题分析神器
什么是Arthas?
Arthas 是一款线上监控诊断平台,可以实时查看应用 load、内存、gc、线程的状态信息,可以在不修改代码的情况,定位问题,分析接口耗时、传参、异常等情况,提高线上问题排查效率
-
GitHub地址:https://github.com/alibaba/arthas
Arthas安装
先将对应的arthas程序下载到本地,可以使用wget
命令,也可以使用官网介绍的curl
访问对应链接
wget https://arthas.aliyun.com/arthas-boot.jar
然后安装文档,启动对应的jar
java -jar arthas-boot.jar --repo-mirror aliyun --use-http
发现启动时候报错了,报错如下所示:
Can not find java process. Try to run `jps` command lists the instrumented Java HotSpot VMs on the target system.
Please select an available pid.
如图所示:
原因是因为要加上对应的线程id,但是我们没有运行对应的Java程序,所以可以去官网下载一个Java程序的例子math-game.jar
然后先java -jar math-game.jar
,运行对应的Java程序
查看运行的Java程序:
ps -aux|grep java
可以找到math-game.jar
对应的pid是2266,所以现在再执行
java -jar /usr/local/arthas/arthas-boot.jar 2266
trace命令的使用
下面给出例子,分析一个接口加载慢问题
trace命令可以用于分析哪里耗时比较长,比如我们要分析一个类OrderServiceImpl中的listOrder方法,就可以使用命令
trace com.sample.order.orderServiceImpl listOrder -n 1 --skipJDKMethod
false
-n
是指定捕捉结果的次数,如果接口调用次数比较多,就可以适当加捕捉结果次数
--skipJDKMethod false
是打开jdk方法的打印,其实一般情况都可以不加,因为jdk方法相对比较稳定
如何等接口调用,也可以手动调用接口,就可以打印出如下的监控信息,具体那里加载慢都可以定位到
--[100.00% 3434.755668ms ] org.springframework.cglib.proxy.MethodInterceptor:intercept()
`---[100.00% 3434.620187ms ] cn.test.server.business.VisitorBusiness:getStaffList()
+---[0.00% 0.045431ms ] cn.test.client.dto.StaffListReqDto:getComId() #188
+---[0.00% 0.019135ms ] cn.core.common.utils.CoreUtils:isEmpty() #188
+---[0.00% 0.021816ms ] cn.hutool.core.date.DateUtil:timer() #192
+---[0.00% 0.019987ms ] com.google.common.base.Splitter:on() #194
+---[0.00% 0.005501ms ] cn.test.client.dto.StaffListReqDto:getComId() #194
+---[0.00% 0.026292ms ] com.google.common.base.Splitter:splitToList() #194
+---[0.00% 0.131507ms ] cn.hutool.core.convert.Convert:toInt() #195
+---[0.34% 11.668407ms ] cn.core.user.client.querier.SchoolQuerierService:findBySchoolId() #198
+---[0.00% 0.024199ms ] cn.hutool.core.date.TimeInterval:intervalRestart() #203
+---[0.02% 0.535107ms ] org.slf4j.Logger:info() #203
+---[2.66% 91.504718ms ] cn.core.user.client.querier.RelationQuerierService:queryUserByIdsAndRoleType() #206
+---[0.00% 0.019208ms ] com.google.common.collect.Lists:newArrayList() #206
+---[0.00% 0.01107ms ] cn.core.common.utils.CoreUtils:isEmpty() #207
+---[0.00% 0.013517ms ] cn.hutool.core.date.TimeInterval:intervalRestart() #211
+---[0.02% 0.532242ms ] org.slf4j.Logger:info() #211
+---[0.00% 0.016216ms ] cn.hutool.core.date.TimeInterval:intervalRestart() #218
+---[0.01% 0.435469ms ] org.slf4j.Logger:info() #218
+---[0.00% 0.009024ms ] cn.test.client.dto.StaffListReqDto:getComId() #221
+---[0.53% 18.336268ms ]cn.test.persistence.dao.LogMapper:listStaffSyncRecordByComId() #221
+---[0.00% 0.009043ms ] com.google.common.collect.Lists:newArrayList() #221
+---[0.00% 0.019237ms ] cn.hutool.core.date.TimeInterval:intervalRestart() #223
+---[0.01% 0.279834ms ] org.slf4j.Logger:info() #223
+---[0.00% 0.014057ms ] cn.hutool.core.date.TimeInterval:intervalRestart() #227
+---[0.01% 0.270155ms ] org.slf4j.Logger:info() #227
+---[0.00% 0.006338ms ] com.google.common.collect.Lists:newArrayList() #231
+---[0.00% 0.019707ms ] cn.hutool.core.date.TimeInterval:intervalRestart() #263
+---[0.02% 0.548875ms ] org.slf4j.Logger:info() #263
`---[0.00% 0.027475ms ] cn.test.client.dto.Result:success() #265
如果要打印接口里耗时大于多少毫秒,就可以使用命令,如下是筛选大于100ms的
trace com.sample.order.orderServiceImpl listOrder '#cost > 100' -n 1