Arthas:线上问题排查工具

 

安装#

下载

Copy

java -jar arthas-boot.jar

查看版本：#

Copy

D:\Program Files\arthas $ java -jar arthas-boot.jar -version [INFO] arthas-boot version: 3.1.0 Local versions: 3.1.0 Remote versions: 3.1.0 3.0.5 3.0.4 3.0.3 3.0.0-RC 3.0.5

命令使用#

启动arthas#

Copy

E:\BaiduYunDownload\arthas-packaging-3.1.0-bin $ java -jar arthas-boot.jar [INFO] arthas-boot version: 3.1.0 [INFO] Found existing java process, please choose one and hit RETURN. * [1]: 22596 org.jetbrains.idea.maven.server.RemoteMavenServer [2]: 20728 org.apache.catalina.startup.Bootstrap [3]: 29752 com.shitou.Application [4]: 37144 [5]: 15660 org.jetbrains.jps.cmdline.Launcher 3 [INFO] arthas home: E:\BaiduYunDownload\arthas-packaging-3.1.0-bin [INFO] Try to attach process 29752 [INFO] Found java home from System Env JAVA_HOME: D:\Program Files\Java\jdk1.8.0 [INFO] Attach process 29752 success. [INFO] arthas-client connect 127.0.0.1 3658 ,---. ,------. ,--------.,--. ,--. ,---. ,---. / O \ | .--. ''--. .--'| '--' | / O \ ' .-' | .-. || '--'.' | | | .--. || .-. |`. `-. | | | || |\ \ | | | | | || | | |.-' | `--' `--'`--' '--' `--' `--' `--'`--' `--'`-----' wiki: https://alibaba.github.io/arthas version: 3.1.0 pid: 29752 time: 2019-03-20 18:21:26

查看dashboard#

Copy

ID NAME GROUP PRIORIT STATE %CPU TIME INTERRU DAEMON 67 Abandoned connection clea main 5 TIMED_WA 0 0:0 false true 128 AsyncAppender-Worker-arth system 5 WAITING 0 0:0 false true 6 Attach Listener system 5 RUNNABLE 0 0:0 false true 65 ContainerBackgroundProces main 5 TIMED_WA 0 0:0 false true 122 DestroyJavaVM main 5 RUNNABLE 0 0:52 false false 68 Druid-ConnectionPool-Crea main 5 WAITING 0 0:0 false true 69 Druid-ConnectionPool-Dest main 5 TIMED_WA 0 0:0 false true 92 DubboClientReconnectTimer main 5 WAITING 0 0:0 false true 96 DubboClientReconnectTimer main 5 TIMED_WA 0 0:0 false true 79 DubboRegistryFailedRetryT main 5 TIMED_WA 0 0:0 false true 125 DubboResponseTimeoutScanT main 5 TIMED_WA 0 0:0 false true 83 DubboSaveRegistryCache-th main 5 WAITING 0 0:0 false true Memory used total max usage GC heap 160M 320M 4050M 3.96% gc.parnew.count 155 par_eden_space 5M 68M 266M 2.17% gc.parnew.time(ms) 1154 par_survivor_space 711K 8704K 34048K 2.09% gc.concurrentmarksweep.co 7 cms_old_gen 153M 243M 3751M 4.10% unt nonheap 171M 180M -1 94.88% gc.concurrentmarksweep.ti 429 code_cache 25M 25M 240M 10.77% me(ms) Runtime os.name Windows 10 os.version 10.0 java.version 1.8.0_201 java.home D:\Program Files\Java\jdk 1.8.0\jre systemload.average -1.00

数据说明#

• ID: Java级别的线程ID，注意这个ID不能跟jstack中的nativeID一一对应
• NAME: 线程名
• GROUP: 线程组名
• PRIORITY: 线程优先级, 1~10之间的数字，越大表示优先级越高
• STATE: 线程的状态
• CPU%: 线程消耗的cpu占比，采样100ms，将所有线程在这100ms内的cpu使用量求和，再算出每个线程的cpu使用占比。
• TIME: 线程运行总时间，数据格式为分：秒
• INTERRUPTED: 线程当前的中断位状态
• DAEMON: 是否是daemon线程

thread:线程信息#

显示所有线程信息#

Copy

$ thread Threads Total: 80, NEW: 0, RUNNABLE: 23, BLOCKED: 0, WAITING: 33, TIMED_WAITING: 24, TERMINATED: 0 ID NAME GROUP PRIORIT STATE %CPU TIME INTERRU DAEMON 67 Abandoned connection clea main 5 TIMED_WA 0 0:0 false true 128 AsyncAppender-Worker-arth system 5 WAITING 0 0:0 false true 6 Attach Listener system 5 RUNNABLE 0 0:0 false true 65 ContainerBackgroundProces main 5 TIMED_WA 0 0:0 false true 122 DestroyJavaVM main 5 RUNNABLE 0 0:52 false false 68 Druid-ConnectionPool-Crea main 5 WAITING 0 0:0 false true 69 Druid-ConnectionPool-Dest main 5 TIMED_WA 0 0:0 false true 92 DubboClientReconnectTimer main 5 WAITING 0 0:0 false true 96 DubboClientReconnectTimer main 5 TIMED_WA 0 0:0 false true

显示当前最忙的前n个线程，并打印出堆栈#

Copy

$ thread -n 3 "Reference Handler" Id=2 cpuUsage=0% WAITING on java.lang.ref.Reference$Lock@5889e097 at java.lang.Object.wait(Native Method) - waiting on java.lang.ref.Reference$Lock@5889e097 at java.lang.Object.wait(Object.java:502) at java.lang.ref.Reference.tryHandlePending(Reference.java:191) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153) "Finalizer" Id=3 cpuUsage=0% WAITING on java.lang.ref.ReferenceQueue$Lock@2c5e60e3 at java.lang.Object.wait(Native Method) - waiting on java.lang.ref.ReferenceQueue$Lock@2c5e60e3 at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216) "Signal Dispatcher" Id=5 cpuUsage=0% RUNNABLE

查看指定线程的堆栈信息#

Copy

$ thread 2 "Reference Handler" Id=2 WAITING on java.lang.ref.Reference$Lock@5889e097 at java.lang.Object.wait(Native Method) - waiting on java.lang.ref.Reference$Lock@5889e097 at java.lang.Object.wait(Object.java:502) at java.lang.ref.Reference.tryHandlePending(Reference.java:191) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153) Affect(row-cnt:0) cost in 56 ms.

找出当前阻塞其他线程的线程#

Copy

$ thread -b No most blocking thread found! Affect(row-cnt:0) cost in 68 ms.

指定采样时间间隔#

Copy

$ thread -n 3 -i 10000 "File Watcher" Id=101 cpuUsage=88% TIMED_WAITING at java.lang.Thread.sleep(Native Method) at org.springframework.boot.devtools.filewatch.FileSystemWatcher$Watcher.scan(FileSystemWatcher.java:249) at org.springframework.boot.devtools.filewatch.FileSystemWatcher$Watcher.run(FileSystemWatcher.java:239) at java.lang.Thread.run(Thread.java:748) "Hashed wheel timer #1" Id=89 cpuUsage=9% TIMED_WAITING at java.lang.Thread.sleep(Native Method) at org.jboss.netty.util.HashedWheelTimer$Worker.waitForNextTick(HashedWheelTimer.java:503) at org.jboss.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:401) at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108) at java.lang.Thread.run(Thread.java:748) "http-nio-18080-exec-7" Id=111 cpuUsage=1% WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@fefdf30 at sun.misc.Unsafe.park(Native Method) - waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@fefdf30 at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:103) at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:31) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.lang.Thread.run(Thread.java:748) Affect(row-cnt:0) cost in 10062 ms.

watch:查看方法的入参出参：#

Copy

$ watch com.shitou.huishi.contract.datacontract.service.web.OrderApplyInfoService readCreditDetailByLoanOrderId "{params[0],returnObj}" -b -f Press Q or Ctrl+C to abort. Affect(class-cnt:2 , method-cnt:2) cost in 136 ms. ts=2019-03-21 16:10:14; [cost=0.01548ms] result=@ArrayList[ @LoanOrderKeyReq[LoanOrderKeyReq(loanOrderId=PO119110867372605450)], null, ] ts=2019-03-21 16:10:14; [cost=0.011808ms] result=@ArrayList[ @LoanOrderKeyReq[LoanOrderKeyReq(loanOrderId=PO119110867372605450)], null, ] ts=2019-03-21 16:10:15; [cost=56.043046ms] result=@ArrayList[ @LoanOrderKeyReq[LoanOrderKeyReq(loanOrderId=PO119110867372605450)], @DataResponse[DataResponse(data=ApplyInfoDTO(loanOrderId=PO119110867372605450, orgSource=及时雨, productName=小微企业经营贷, lenderName=小米科技, lenderNo=544619676, lenderNoType=null, applyMoney=60000.00, applyPeriod=55, applyYearRate=63.0000, repaymentType=xxhb_rt, isCredit=0, loanUsage=gmsb_lu, loanUsageDesc=xxxxxxxxxxxxxx, ensureType=dy_bz_zy_et, isSmallLoan=null, showExpireTime=null, doorReview=tangy, conditionAdd=null, isXudai=null))], ] ts=2019-03-21 16:10:15; [cost=61.627293ms] result=@ArrayList[ @LoanOrderKeyReq[LoanOrderKeyReq(loanOrderId=PO119110867372605450)], @DataResponse[DataResponse(data=ApplyInfoDTO(loanOrderId=PO119110867372605450, orgSource=及时雨, productName=小微企业经营贷, lenderName=小米科技, lenderNo=544619676, lenderNoType=null, applyMoney=60000.00, applyPeriod=55, applyYearRate=63.0000, repaymentType=xxhb_rt, isCredit=0, loanUsage=gmsb_lu, loanUsageDesc=xxxxxxxxxxxxxx, ensureType=dy_bz_zy_et, isSmallLoan=null, showExpireTime=null, doorReview=tangy, conditionAdd=null, isXudai=null))], ]

前2个是请求参数

后2段是返回参数

对于上面的params,returnObj,具体请查看 表达式核心变量

watch具体参数选项#

[b]	在方法调用之前观察
[e]	在方法异常之后观察
[s]	在方法返回之后观察
[f]	在方法结束之后(正常返回和异常返回)观察
[E]	开启正则表达式匹配，默认为通配符匹配
[x:]	指定输出结果的属性遍历深度，默认为 1

这里特别注意x，遍历深度

深度为1：#

Copy

[arthas@22104]$ watch com.shitou.huishi.manager.impl.RefinanceManageImpl queryQYDHistoryRefinanceOrder "{params[0],returnObj }" -x 1 -b -f Press Q or Ctrl+C to abort. Affect(class-cnt:1 , method-cnt:1) cost in 153 ms. ts=2020-01-02 20:20:16; [cost=0.0103ms] result=@ArrayList[ @String[PO119631178119643150], null, ] ts=2020-01-02 20:20:16; [cost=9.027673849411E8ms] result=@ArrayList[ @String[PO119631178119643150], @ArrayList[isEmpty=false;size=2], ]

深度为2：#

Copy

[arthas@22104]$ watch com.shitou.huishi.manager.impl.RefinanceManageImpl queryQYDHistoryRefinanceOrder "{params[0],returnObj }" -x 2 -b -f Press Q or Ctrl+C to abort. Affect(class-cnt:1 , method-cnt:1) cost in 152 ms. ts=2020-01-02 20:20:31; [cost=0.0106ms] result=@ArrayList[ @String[PO119631178119643150], null, ] ts=2020-01-02 20:20:31; [cost=9.027829001319E8ms] result=@ArrayList[ @String[PO119631178119643150], @ArrayList[ @LoanOrderInfoDTO[LoanOrderInfoDTO(loanOrderId=BO119643577337905166, mainSubjectArchiveId=1000000162, borrowerArchiveId=1000000162, legalArchiveId=null, actualArchiveId=null, loanType=1)], @LoanOrderInfoDTO[LoanOrderInfoDTO(loanOrderId=BO119643622212763658, mainSubjectArchiveId=1000000125, borrowerArchiveId=1000000125, legalArchiveId=1000000099, actualArchiveId=1000000096, loanType=1)], ], ] java.net.SocketException: Connection reset at java.net.SocketInputStream.read(SocketInputStream.java:210) at java.net.SocketInputStream.read(SocketInputStream.java:141) at java.io.BufferedInputStream.read1(BufferedInputStream.java:284) at java.io.BufferedInputStream.read(BufferedInputStream.java:345) at java.io.BufferedInputStream.fill(BufferedInputStream.java:246) at java.io.BufferedInputStream.read(BufferedInputStream.java:265) at org.apache.commons.net.telnet.TelnetInputStream.__read(TelnetInputStream.java:132) at org.apache.commons.net.telnet.TelnetInputStream.run(TelnetInputStream.java:603) at java.lang.Thread.run(Thread.java:748)

可以发现，原来的返回体数组的具体信息都可以看见了。

trace:查看方法内部调用路径，并输出每个节点上面的耗时#

Copy

$ trace com.shitou.huishi.service.agency.AgencyOrderServiceImpl * Press Q or Ctrl+C to abort. Affect(class-cnt:2 , method-cnt:70) cost in 553 ms. `---ts=2020-04-21 14:47:05;thread_name=http-nio-18080-exec-6;id=1b0;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@7bf74eb1 `---[231.0472ms] com.shitou.huishi.service.agency.AgencyOrderServiceImpl$$EnhancerBySpringCGLIB$$b4405138:submitAgencyOrderInfo() `---[224.8126ms] org.springframework.cglib.proxy.MethodInterceptor:intercept() `---[137.4045ms] com.shitou.huishi.service.agency.AgencyOrderServiceImpl:submitAgencyOrderInfo() +---[1.9188ms] java.lang.StringBuilder:<init>() +---[min=0.0047ms,max=0.0584ms,total=0.0689ms,count=3] java.lang.StringBuilder:append() +---[0.0137ms] com.shitou.huishi.contract.datacontract.request.agency.SubmitAgencyOrderInfoRequest:getAgencyToken() +---[0.0153ms] java.lang.StringBuilder:toString() +---[0.0409ms] org.apache.curator.framework.recipes.locks.InterProcessMutex:<init>() +---[3.3824ms] org.apache.curator.framework.recipes.locks.InterProcessMutex:acquire() +---[1.72ms] com.shitou.huishi.agency.helper.AgencyAuthHelper:getAgencyUser() +---[0.0197ms] com.shitou.huishi.config.GlobalConfig:getIsHandXSAuth() +---[0.02ms] java.lang.Boolean:booleanValue() +---[19.3857ms] com.shitou.huishi.agency.manager.AgencyOrderManager:saveAgencyOrderInfo() +---[27.697ms] com.shitou.huishi.agency.manager.AgencyOrderManager:submitAgencyOrderInfo() +---[0.0188ms] com.shitou.huishi.domain.entity.AgencyOrderInfo:getLoanOrderId() +---[61.3922ms] com.shitou.huishi.manager.LoanOrderManager:initOrderInfo() +---[15.8171ms] com.shitou.huishi.agency.manager.AgencyLogManager:saveAgencyOrderInfoLog() +---[0.0135ms] com.shitou.huishi.domain.entity.AgencyOrderInfo:getAgencyOrderId() +---[0.0162ms] com.shitou.huishi.contract.datacontract.response.DataResponse:process() +---[0.0095ms] org.apache.curator.framework.recipes.locks.InterProcessMutex:isAcquiredInThisProcess() +---[0.5194ms] org.slf4j.Logger:info() `---[1.7714ms] org.apache.curator.framework.recipes.locks.InterProcessMutex:release()

命令 trace 类名 方法名

trace只显示方法内方法的执行时间，但是再下一级的时间就需要自己再次手动调用

Copy

$ trace com.shitou.huishi.manager.LoanOrderManager initOrderInfo Press Q or Ctrl+C to abort. Affect(class-cnt:2 , method-cnt:2) cost in 1031 ms. `---ts=2020-04-21 14:47:41;thread_name=http-nio-18080-exec-5;id=1af;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@7bf74eb1 `---[71.1404ms] com.shitou.huishi.manager.impl.LoanOrderManagerImpl$$EnhancerBySpringCGLIB$$a059faf9:initOrderInfo() `---[70.9246ms] org.springframework.cglib.proxy.MethodInterceptor:intercept() `---[69.8022ms] com.shitou.huishi.manager.impl.LoanOrderManagerImpl:initOrderInfo() +---[4.3738ms] com.shitou.huishi.domain.LoanOrderBizFacade:selectByPrimaryKey() +---[0.0173ms] com.shitou.huishi.domain.entity.ModifyLoanOrderInfo:<init>() +---[0.01ms] com.shitou.huishi.domain.entity.ModifyLoanOrderInfo:setLoanOrderId() +---[0.0122ms] com.shitou.huishi.domain.entity.LoanOrder:getBelongName() +---[0.0084ms] com.shitou.huishi.domain.entity.ModifyLoanOrderInfo:setAfterBelongName() +---[0.0083ms] com.shitou.huishi.domain.entity.LoanOrder:getBelongDisplayName() +---[0.0077ms] com.shitou.huishi.domain.entity.ModifyLoanOrderInfo:setAfterBelongDisplayName() +---[0.0069ms] com.shitou.huishi.domain.entity.LoanOrder:getBelongDeptName() +---[0.0062ms] com.shitou.huishi.domain.entity.ModifyLoanOrderInfo:setAfterBelongDepartmentName() +---[0.0102ms] com.shitou.huishi.domain.entity.LoanOrder:getCreateName() +---[0.0068ms] com.shitou.huishi.domain.entity.ModifyLoanOrderInfo:setCreateName() +---[0.0078ms] java.util.Date:<init>() +---[0.0071ms] com.shitou.huishi.domain.entity.ModifyLoanOrderInfo:setChangeDate() +---[2.5918ms] com.shitou.huishi.domain.ModifyLoanOrderInfoBizFacade:insertSelective() +---[min=0.0058ms,max=0.0164ms,total=0.0317ms,count=3] com.shitou.huishi.domain.entity.LoanOrder:getMainSubjectArchiveId() +---[0.0395ms] com.shitou.huishi.contract.datacontract.dto.assets.InitAssetsDto:<init>() +---[min=0.0045ms,max=0.0064ms,total=0.0163ms,count=3] java.lang.Integer:<init>() +---[min=0.0063ms,max=0.0074ms,total=0.0201ms,count=3] java.lang.reflect.Method:invoke() +---[9.9859ms] com.shitou.huishi.manager.AssetsManager:initAssetsByNewest() +---[0.0152ms] com.shitou.huishi.contract.datacontract.dto.assets.InitAssetsDebtDto:<init>() +---[9.5382ms] com.shitou.huishi.manager.AssetsManager:initAssetsDebtByNewest() +---[min=0.0059ms,max=0.0157ms,total=0.0216ms,count=2] com.shitou.huishi.domain.entity.LoanOrder:getLoanOrderId() +---[0.0379ms] com.shitou.huishi.contract.datacontract.dto.assets.InitIncomeFeesDto:<init>() +---[9.8176ms] com.shitou.huishi.manager.IncomeFeesManager:initIncomeFeesByNewest() +---[min=0.0063ms,max=0.018ms,total=0.0243ms,count=2] com.shitou.huishi.domain.entity.LoanOrder:getLoanType() +---[min=0.0068ms,max=0.0092ms,total=0.016ms,count=2] com.shitou.huishi.base.enums.LoanTypeEnum:getStatus() +---[min=0.0046ms,max=0.022ms,total=0.0266ms,count=2] java.lang.Integer:valueOf() +---[min=0.0054ms,max=0.0314ms,total=0.0368ms,count=2] java.lang.Integer:equals() +---[0.0091ms] com.shitou.huishi.domain.entity.LoanOrder:getBorrowerArchiveId() +---[0.0091ms] com.shitou.huishi.contract.datacontract.request.relation.OrderRelationQuery:<init>() +---[6.5657ms] com.shitou.huishi.manager.RelationManage:sysnRelation() `---[25.1437ms] com.shitou.huishi.manager.impl.LoanOrderManagerImpl:initLoanOrderDetail()

Copy

$ trace com.shitou.huishi.manager.impl.LoanOrderManagerImpl initLoanOrderDetail Press Q or Ctrl+C to abort. Affect(class-cnt:2 , method-cnt:1) cost in 1045 ms. `---ts=2020-04-21 14:48:35;thread_name=http-nio-18080-exec-7;id=1b1;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@7bf74eb1 `---[21.0879ms] com.shitou.huishi.manager.impl.LoanOrderManagerImpl:initLoanOrderDetail() +---[0.0338ms] com.shitou.huishi.domain.entity.LoanOrder:getLoanOrderId() +---[3.4537ms] com.shitou.huishi.domain.LoanOrderDetailBizFacade:selectByPrimaryKey() +---[14.5324ms] com.shitou.huishi.manager.impl.RefinanceManageImpl:queryContinuedLoanOrderRelation() +---[0.0053ms] java.lang.Integer:<init>() +---[0.0052ms] java.lang.reflect.Method:invoke() +---[0.0231ms] java.util.List:isEmpty() +---[0.0215ms] java.lang.Boolean:valueOf() +---[0.0106ms] com.shitou.huishi.domain.entity.LoanOrderDetail:setIsSystemXudai() `---[2.6394ms] com.shitou.huishi.domain.LoanOrderDetailBizFacade:updateByPrimaryKeySelective()

这样就可以一级一级查看具体执行时间

可以调用业务实现类，也可以调用接口声明类，结果都一样

也可以模糊匹配

Copy

trace com.shitou.huishi.contract.datacontract.service.agency.AgencyOrderService * trace com.shitou.huishi.contract.datacontract.service.agency.AgencyOrderService submitAgencyOrderInfo

stack:查看当前方法调用路径#

Copy

$ stack com.shitou.huishi.contract.datacontract.service.web.OrderApplyInfoService readCreditDetailByLoanOrderId Press Q or Ctrl+C to abort. Affect(class-cnt:2 , method-cnt:2) cost in 181 ms. ts=2019-03-21 16:19:04;thread_name=http-nio-8083-exec-8;id=3d;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@34018c56 @com.shitou.huishi.service.web.OrderApplyInfoServiceImpl$$FastClassBySpringCGLIB$$1213e5f9.invoke() at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204) at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:738) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:85) at com.shitou.huishi.aop.ControllerAspect.aroundAdvice(ControllerAspect.java:61) at sun.reflect.GeneratedMethodAccessor161.invoke(null:-1) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:629) at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:618) at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673) at com.shitou.huishi.service.web.OrderApplyInfoServiceImpl$$EnhancerBySpringCGLIB$$1a8938.readCreditDetailByLoanOrderId(<generated>:-1) at sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-2) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205) at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:133) at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:97) at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827) at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738) at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85) at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967) at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901) at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970) at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872) at javax.servlet.http.HttpServlet.service(HttpServlet.java:707) at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846) at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.boot.web.filter.ApplicationContextHeaderFilter.doFilterInternal(ApplicationContextHeaderFilter.java:55) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at com.alibaba.druid.support.http.WebStatFilter.doFilter(WebStatFilter.java:123) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.boot.actuate.trace.WebRequestTraceFilter.doFilterInternal(WebRequestTraceFilter.java:110) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:105) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:81) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.boot.actuate.autoconfigure.MetricsFilter.doFilterInternal(MetricsFilter.java:106) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:80) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342) at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:799) at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:861) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1455) at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.lang.Thread.run(Thread.java:745)

tt:记录下指定方法的调用，后续对其进行筛选，查看，重现等#

开始记录：#

Copy

$ tt -t com.shitou.huishi.contract.datacontract.service.web.OrderApplyInfoService readCreditDetailByLoanOrderId Press Q or Ctrl+C to abort. Affect(class-cnt:2 , method-cnt:2) cost in 160 ms. INDEX TIMESTAMP COST(ms) IS-RET IS-EXP OBJECT CLASS METHOD ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ 1000 2019-03-21 16:37:05 62.710494 true false 0x4adf3582 OrderApplyInfoServiceImpl readCreditDetailByLoanOrderId 1001 2019-03-21 16:37:05 -0.022655 true false 0x708c8fb OrderApplyInfoServiceImpl$$EnhancerBySpringCGLIB$$1a8938 readCreditDetailByLoanOrderId 1002 2019-03-21 16:37:14 44.213677 true false 0x4adf3582 OrderApplyInfoServiceImpl readCreditDetailByLoanOrderId 1003 2019-03-21 16:37:14 -0.00271 true false 0x708c8fb OrderApplyInfoServiceImpl$$EnhancerBySpringCGLIB$$1a8938 readCreditDetailByLoanOrderId 1004 2019-03-21 16:37:55 59.234538 true false 0x4adf3582 OrderApplyInfoServiceImpl readCreditDetailByLoanOrderId 1005 2019-03-21 16:37:55 -0.00376 true false 0x708c8fb OrderApplyInfoServiceImpl$$EnhancerBySpringCGLIB$$1a8938 readCreditDetailByLoanOrderId 1006 2019-03-21 16:38:01 57.618517 true false 0x4adf3582 OrderApplyInfoServiceImpl readCreditDetailByLoanOrderId 1007 2019-03-21 16:38:01 -0.003653 true false 0x708c8fb OrderApplyInfoServiceImpl$$EnhancerBySpringCGLIB$$1a8938 readCreditDetailByLoanOrderId

查看所有记录：#

Copy

$ tt -l INDEX TIMESTAMP COST(ms) IS-RET IS-EXP OBJECT CLASS METHOD ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ 1000 2019-03-21 16:37:05 62.710494 true false 0x4adf3582 OrderApplyInfoServiceImpl readCreditDetailByLoanOrderId 1001 2019-03-21 16:37:05 -0.022655 true false 0x708c8fb OrderApplyInfoServiceImpl$$EnhancerBySpringCGLIB$$1a8938 readCreditDetailByLoanOrderId 1002 2019-03-21 16:37:14 44.213677 true false 0x4adf3582 OrderApplyInfoServiceImpl readCreditDetailByLoanOrderId 1003 2019-03-21 16:37:14 -0.00271 true false 0x708c8fb OrderApplyInfoServiceImpl$$EnhancerBySpringCGLIB$$1a8938 readCreditDetailByLoanOrderId 1004 2019-03-21 16:37:55 59.234538 true false 0x4adf3582 OrderApplyInfoServiceImpl readCreditDetailByLoanOrderId 1005 2019-03-21 16:37:55 -0.00376 true false 0x708c8fb OrderApplyInfoServiceImpl$$EnhancerBySpringCGLIB$$1a8938 readCreditDetailByLoanOrderId 1006 2019-03-21 16:38:01 57.618517 true false 0x4adf3582 OrderApplyInfoServiceImpl readCreditDetailByLoanOrderId 1007 2019-03-21 16:38:01 -0.003653 true false 0x708c8fb OrderApplyInfoServiceImpl$$EnhancerBySpringCGLIB$$1a8938 readCreditDetailByLoanOrderId Affect(row-cnt:8) cost in 11 ms.

对记录进行筛选：#

比如对请求 参数进行筛选：

Copy

$ tt -s "params[0].loanOrderId=='BO119643577337905166'" INDEX TIMESTAMP COST(ms) IS-RET IS-EXP OBJECT CLASS METHOD ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ 1006 2019-03-21 16:38:01 57.618517 true false 0x4adf3582 OrderApplyInfoServiceImpl readCreditDetailByLoanOrderId 1007 2019-03-21 16:38:01 -0.003653 true false 0x708c8fb OrderApplyInfoServiceImpl$$EnhancerBySpringCGLIB$$1a8938 readCreditDetailByLoanOrderId Affect(row-cnt:2) cost in 21 ms.

查看具体记录信息：#

Copy

$ tt -i 1006 INDEX 1006 GMT-CREATE 2019-03-21 16:38:01 COST(ms) 57.618517 OBJECT 0x4adf3582 CLASS com.shitou.huishi.service.web.OrderApplyInfoServiceImpl METHOD readCreditDetailByLoanOrderId IS-RETURN true IS-EXCEPTION false PARAMETERS[0] @LoanOrderKeyReq[ serialVersionUID=@Long[8109590394803201418], loanOrderId=@String[BO119643577337905166], ] RETURN-OBJ @DataResponse[ serialVersionUID=@Long[-2479705076778238646], data=@ApplyInfoDTO[ApplyInfoDTO(loanOrderId=BO119643577337905166, orgSource=及时雨, productName=小微企业经营贷, lenderName=张爱青, lenderNo=99988882, lenderNoType=null, applyMoney=5.00, applyPeriod=24, applyYearRate=63.0000, repaymentType=xxhb_rt, isCredit=0, lo anUsage=gmsb_lu, loanUsageDesc=xxxxxxxxxxxxxx, ensureType=dy_bz_zy_et, isSmallLoan=null, showExpireTime=null, doorReview=null, conditionAdd=null, isXudai=null)], ] Affect(row-cnt:1) cost in 13 ms.

重做一次调用：#

Copy

$ tt -i 1006 -p RE-INDEX 1006 GMT-REPLAY 2019-03-21 16:45:20 OBJECT 0x4adf3582 CLASS com.shitou.huishi.service.web.OrderApplyInfoServiceImpl METHOD readCreditDetailByLoanOrderId PARAMETERS[0] @LoanOrderKeyReq[ serialVersionUID=@Long[8109590394803201418], loanOrderId=@String[BO119643577337905166], ] IS-RETURN true IS-EXCEPTION false COST(ms) 50.881621 RETURN-OBJ @DataResponse[ serialVersionUID=@Long[-2479705076778238646], data=@ApplyInfoDTO[ApplyInfoDTO(loanOrderId=BO119643577337905166, orgSource=及时雨, productName=小微企业经营贷, lenderName=张爱青, lenderNo=99988882, lenderNoType=null, applyMoney=5.00, applyPeriod=24, applyYearRate=63.0000, repaymentType=xxhb_rt, isCredit=0, lo anUsage=gmsb_lu, loanUsageDesc=xxxxxxxxxxxxxx, ensureType=dy_bz_zy_et, isSmallLoan=null, showExpireTime=null, doorReview=null, conditionAdd=null, isXudai=null)], ] Time fragment[1006] successfully replayed.

参考：#

Arthas 用户文档