1
一文带你快速了解 Java 线上问题快速诊断神器 Arthas
作者：zuozewei
- 2022 年 1 月 16 日
本文字数：13611 字
阅读完需：约 45 分钟
一、什么是 Arthas
Arthas 是 Alibaba 开源的一款 Java 诊断工具，能够查看 Java 应用的线程状态、JVM 信息等，支持在线对业务问题诊断，比如查看方法调用的出入参、执行过程、抛出的异常、输出方法执行耗时等，大大提升了线上问题的排查效率。
官网：https://arthas.aliyun.com/zh-cn/
二、特性一览
三、Arthas 能为你做什么？
你遇到以下类似问题而束手无策时，Arthas 可以帮助你解决：
这个类从哪个 jar 包加载的？为什么会报各种类相关的 Exception？
我改的代码为什么没有执行到？难道是我没 commit？分支搞错了？
遇到问题无法在线上 debug，难道只能通过加日志再重新发布吗？
线上遇到某个用户的数据处理有问题，但线上同样无法 debug，线下无法重现！
是否有一个全局视角来查看系统的运行状况？
有什么办法可以监控到 JVM 的实时运行状态？
怎么快速定位应用的热点，生成火焰图？
怎样直接从 JVM 内查找某个类的实例？
Arthas 支持 JDK 6+，支持 Linux/Mac/Windows，采用命令行交互模式，同时提供丰富的 Tab 自动补全功能，进一步方便进行问题的定位和诊断。
四、快速安装
1、前提条件
[root@c41287379b7c /]# yum install telnet[root@c41287379b7c /]# yum install unzip复制代码
2、一键安装
使用命令下载 Arthas 脚本：
[root@c41287379b7c /]# curl -L https://alibaba.github.io/arthas/install.sh | sh % Total % Received % Xferd Average Speed Time Time Time Current Dload Upload Total Spent Left Speed100 961 100 961 0 0 743 0 0:00:01 0:00:01 --:--:-- 743downloading... ./as.sh.1598Arthas install successed.复制代码
使用命令下载 Arthas jar 包：
curl -O https://arthas.aliyun.com/arthas-boot.jarjava -jar arthas-boot.jar
复制代码
Arthas 提供是 jar 包形式，其本质是个 Java 应用。
五、快速使用
1、启动脚本并连接进程
使用脚本快速启动：
[root@c41287379b7c /]# ./as.shArthas script version: 3.1.7[INFO] JAVA_HOME: /usr/jdk1.8.0_111Found existing java process, please choose one and hit RETURN.* [1]: 1 org.apache.catalina.startup.Bootstrap1 //这里输入1就是连接进程，如果有多个java进程，将在这里出现一个list，输入序号即可连接进程。updating version 3.1.7 ...Download arthas from: https://repo1.maven.org/maven2/com/taobao/arthas/arthas-packaging/3.1.7/arthas-packaging-3.1.7-bin.zip######################################################################## 100.0%Archive: /tmp/temp_3.1.7_1673/arthas-3.1.7-bin.zip creating: /tmp/temp_3.1.7_1673/async-profiler/ inflating: /tmp/temp_3.1.7_1673/arthas-spy.jar inflating: /tmp/temp_3.1.7_1673/arthas-agent.jar inflating: /tmp/temp_3.1.7_1673/arthas-client.jar inflating: /tmp/temp_3.1.7_1673/arthas-boot.jar inflating: /tmp/temp_3.1.7_1673/arthas-demo.jar inflating: /tmp/temp_3.1.7_1673/install-local.sh inflating: /tmp/temp_3.1.7_1673/as.sh inflating: /tmp/temp_3.1.7_1673/as.bat inflating: /tmp/temp_3.1.7_1673/as-service.bat inflating: /tmp/temp_3.1.7_1673/async-profiler/libasyncProfiler-linux-x64.so inflating: /tmp/temp_3.1.7_1673/async-profiler/libasyncProfiler-mac-x64.so inflating: /tmp/temp_3.1.7_1673/arthas-core.jarupdate completed.Arthas home: /root/.arthas/lib/3.1.7/arthasCalculating attach execution time...Attaching to 1 using version /root/.arthas/lib/3.1.7/arthas...
real 0m2.298suser 0m0.302ssys 0m0.145sAttach success.telnet connecting to arthas server... current timestamp is 1583537651Trying 127.0.0.1...Connected to 127.0.0.1.Escape character is '^]'. ,---. ,------. ,--------.,--. ,--. ,---. ,---. / O \ | .--. ''--. .--'| '--' | / O \ ' .-'| .-. || '--'.' | | | .--. || .-. |`. `-.| | | || |\ \ | | | | | || | | |.-' |`--' `--'`--' '--' `--' `--' `--'`--' `--'`-----'
wiki https://alibaba.github.io/arthastutorials https://alibaba.github.io/arthas/arthas-tutorialsversion 3.1.7pid 1time 2020-03-06 23:34:10
[arthas@1]$复制代码
2、启动 jar 包并连接进程
执行该程序的用户需要和目标进程具有相同的权限。
比如以 admin 用户来执行：
sudo su admin && java -jar arthas-boot.jar或 sudo -u admin -EH java -jar arthas-boot.jar复制代码
如果 attach 不上目标进程，可以查看 ~/logs/arthas/ 目录下的日志。
如果下载速度比较慢，可以使用 aliyun 的镜像：
java -jar arthas-boot.jar --repo-mirror aliyun --use-http复制代码
java -jar arthas-boot.jar -h #打印更多参数信息。复制代码
选择应用 java 进程：
$ $ java -jar arthas-boot.jar* [1]: 35542 [2]: 71560 math-game.jar复制代码
math-game 进程是第 2 个，则输入 2，再输入回车 /enter。Arthas 会 attach 到目标进程上，并输出日志：
[INFO] Try to attach process 71560[INFO] Attach process 71560 success.[INFO] arthas-client connect 127.0.0.1 3658 ,---. ,------. ,--------.,--. ,--. ,---. ,---. / O \ | .--. ''--. .--'| '--' | / O \ ' .-'| .-. || '--'.' | | | .--. || .-. |`. `-.| | | || |\ \ | | | | | || | | |.-' |`--' `--'`--' '--' `--' `--' `--'`--' `--'`-----' wiki: https://arthas.aliyun.com/docversion: 3.0.5.20181127201536pid: 71560time: 2020-11-28 19:16:24 $复制代码
出现 Arthas Logo 之后便可以正常使用了。
六、使用示例
1、dashboard（当前系统的实时数据面板）
ID NAME GROUP PRIORITY STATE %CPU TIME INTERRUPTE DAEMON1572 http-nio-8080-exec-139 main 5 TIMED_WAITI 18 0:12 false true1561 http-nio-8080-exec-138 main 5 RUNNABLE 17 0:18 false true1539 http-nio-8080-exec-131 main 5 TIMED_WAITI 10 1:17 false true1575 http-nio-8080-exec-141 main 5 TIMED_WAITI 10 0:0 false true1573 http-nio-8080-exec-140 main 5 TIMED_WAITI 9 0:8 false true1559 http-nio-8080-exec-136 main 5 TIMED_WAITI 8 0:29 false true1558 grpc-default-executor-1340 main 5 TIMED_WAITI 4 0:5 false true28 grpc-default-worker-ELG-1-4 main 5 RUNNABLE 4 6:44 false true1560 http-nio-8080-exec-137 main 5 RUNNABLE 4 0:23 false trueMemory used total max usage GCheap 155M 311M 843M 18.47% gc.ps_scavenge.count 6631ps_eden_space 39M 171M 310M 12.72% gc.ps_scavenge.time(ms) 52792ps_survivor_space 1M 2M 2M 90.63% gc.ps_marksweep.count 21ps_old_gen 114M 138M 632M 18.10% gc.ps_marksweep.time(ms) 11572Runtimeos.name Linuxos.version 3.10.0-1062.9.1.el7.x86_64java.version 1.8.0_111java.home /usr/jdk1.8.0_111/jre复制代码
2、sysprop（查看或修改 java 属性）
//查看所有属性[arthas@1]$ sysprop KEY VALUE--------------------------------------------------------------------------------------------------------------------------------------- java.vendor Oracle Corporation sun.java.launcher SUN_STANDARD catalina.base /apache-tomcat-8.5.9 sun.management.compiler HotSpot 64-Bit Tiered Compilers...... java.specification.versio 1.8 n
[arthas@1]$//查看特定属性[arthas@1]$ sysprop java.rmi.server.hostnamejava.rmi.server.hostname=106.54.17.234[arthas@1]$ sysprop file.encodingfile.encoding=ANSI_X3.4-1968[arthas@1]$//修改属性[arthas@1]$ sysprop user.countryuser.country=US[arthas@1]$ sysprop user.country CNSuccessfully changed the system property.user.country=CN复制代码
3、mbean（实时查看 Mbean 信息）
参数-i 1000是指定 1 秒刷新一次。
[arthas@1]$ mbean -i 1000 java.lang:type=Threading *Count NAME VALUE-------------------------------- PeakThreadCount 61 DaemonThreadCount 51 ThreadCount 59 TotalStartedThreadCount 1586
复制代码
4、thread（查看线程）
//查看所有线程[arthas@1]$ threadThreads Total: 59, NEW: 0, RUNNABLE: 24, BLOCKED: 0, WAITING: 9, TIMED_WAITING: 26, TERMINATED: 0ID NAME GROUP PRIORIT STATE %CPU TIME INTERRU DAEMON1572 http-nio-8080-exec-139 main 5 TIMED_W 17 1:32 false true1597 http-nio-8080-exec-151 main 5 RUNNABL 15 0:10 false true1539 http-nio-8080-exec-131 main 5 TIMED_W 11 2:37 false true1591 http-nio-8080-exec-148 main 5 RUNNABL 11 0:23 false true1587 http-nio-8080-exec-146 main 5 TIMED_W 9 0:33 false true1585 grpc-default-executor-1 main 5 TIMED_W 5 0:9 false true......Affect(row-cnt:0) cost in 106 ms.[arthas@1]$复制代码
从上面查看所有的 threads 来看 1572 消耗 CPU 17%（此百分比是按单 CPU 计算的）。所以需要查看这个线程在做什么。
//查看指定线程栈信息[arthas@1]$ thread 1572"http-nio-8080-exec-139" Id=1572 RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) at java.net.SocketInputStream.read(SocketInputStream.java:170) at java.net.SocketInputStream.read(SocketInputStream.java:141) at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:100) at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:143) at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:173) - locked com.mysql.jdbc.util.ReadAheadInputStream@afb14dd at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2954) at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3375) at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3365) at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3805) at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2478) at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2625) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2551) - locked com.mysql.jdbc.JDBC4Connection@21123f41 at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1861) - locked com.mysql.jdbc.JDBC4Connection@21123f41 at com.mysql.jdbc.PreparedStatement.execute$original$vADsw8UZ(PreparedStatement.java:1192) - locked com.mysql.jdbc.JDBC4Connection@21123f41 at com.mysql.jdbc.PreparedStatement.execute$original$vADsw8UZ$accessor$md9IHdH2(PreparedStatement.java) ...... Number of locked synchronizers = 1 - java.util.concurrent.ThreadPoolExecutor$Worker@31355af3
Affect(row-cnt:0) cost in 152 ms.[arthas@1]$复制代码
5、thread -n(查看占 CPU 前几的线程栈信息)
查看占 CPU 前 3 的线程栈，间隔 1 秒。
[arthas@1]$ thread -n 3 -i 1000"http-nio-8080-exec-153" Id=1604 cpuUsage=31% RUNNABLE at java.lang.Throwable.fillInStackTrace(Native Method) at java.lang.Throwable.fillInStackTrace(Throwable.java:783) - locked java.lang.NoSuchMethodException@41cb2ff9 at java.lang.Throwable.<init>(Throwable.java:265) at java.lang.Exception.<init>(Exception.java:66) ...... Number of locked synchronizers = 1 - java.util.concurrent.ThreadPoolExecutor$Worker@35ddf68a
"http-nio-8080-exec-150" Id=1595 cpuUsage=27% TIMED_WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@3fb3dff3 at sun.misc.Unsafe.park(Native Method) - waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@3fb3dff3 at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078) at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467) at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:85) at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:31) at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1066) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127) 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)
"http-nio-8080-exec-147" Id=1589 cpuUsage=19% RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) at java.net.SocketInputStream.read(SocketInputStream.java:170) at java.net.SocketInputStream.read(SocketInputStream.java:141) at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:100) at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:143) at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:173) - locked com.mysql.jdbc.util.ReadAheadInputStream@afb14dd ......
Number of locked synchronizers = 1 - java.util.concurrent.ThreadPoolExecutor$Worker@5a014dec
Affect(row-cnt:0) cost in 1140 ms.[arthas@1]$复制代码
6、jad（反编译代码）
[arthas@1]$ jad com.7dgroup.blog.controller.BackBlogController
ClassLoader:+-ParallelWebappClassLoader context: ROOT delegate: false ----------> Parent Classloader: java.net.URLClassLoader@22d7b4f8
+-java.net.URLClassLoader@22d7b4f8 +-sun.misc.Launcher$AppClassLoader@18b4aac2 +-sun.misc.Launcher$ExtClassLoader@5f4fff0
Location:/apache-tomcat-8.5.9/webapps/ROOT/WEB-INF/classes/
/* * Decompiled with CFR. * * Could not load the following classes: * com.7dgroup.blog.common.exception.JsonResponseException ...... */package com.7dgroup.blog.controller;
import com.7dgroup.blog.common.exception.JsonResponseException;import com.7dgroup.blog.common.model.Page;import com.7dgroup.blog.common.model.Response;import com.7dgroup.blog.controller.BackBlogController;import com.7dgroup.blog.model.Blog;import com.7dgroup.blog.model.User;import com.7dgroup.blog.service.BlogReadService;import com.7dgroup.blog.service.BlogWriteService;import com.7dgroup.blog.service.CategoryService;import com.7dgroup.blog.vo.BlogQuery;import java.lang.reflect.Method;import java.util.Date;import java.util.List;import java.util.concurrent.Callable;import javax.servlet.http.HttpSession;import org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.ConstructorInter;import org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.EnhancedInstance;import org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter;import org.springframework.beans.factory.annotation.Autowired;import org.springframework.stereotype.Controller;import org.springframework.ui.Model;import org.springframework.web.bind.annotation.RequestMapping;import org.springframework.web.bind.annotation.RequestParam;import org.springframework.web.bind.annotation.ResponseBody;
@Controller@RequestMapping(value={"/back/blog"})public class BackBlogControllerimplements EnhancedInstance,EnhancedInstance { @Autowired BlogReadService blogReadService; @Autowired BlogWriteService blogWriteService; @Autowired CategoryService categoryService; private volatile Object _$EnhancedClassField_ws; public static volatile /* synthetic */ InstMethodsInter delegate$3vsfol1; public static volatile /* synthetic */ InstMethodsInter delegate$s214mp1; public static volatile /* synthetic */ ConstructorInter delegate$1726vl1; private static final /* synthetic */ Method cachedValue$fhzPhYBQ$0j0d661; private static final /* synthetic */ Method cachedValue$fhzPhYBQ$7jqr912; private static final /* synthetic */ Method cachedValue$fhzPhYBQ$k1ffbv0; private static final /* synthetic */ Method cachedValue$fhzPhYBQ$50tnsu0; public static volatile /* synthetic */ InstMethodsInter delegate$l07kai0; public static volatile /* synthetic */ InstMethodsInter delegate$b310fa0; public static volatile /* synthetic */ ConstructorInter delegate$51jjf90; private static final /* synthetic */ Method cachedValue$CYumwYK8$0j0d661; private static final /* synthetic */ Method cachedValue$CYumwYK8$7jqr912; private static final /* synthetic */ Method cachedValue$CYumwYK8$k1ffbv0; private static final /* synthetic */ Method cachedValue$CYumwYK8$50tnsu0;
public BackBlogController() { this(null); delegate$51jjf90.intercept(this, new Object[0]); }
private /* synthetic */ BackBlogController(auxiliary.xIr7AqvV xIr7AqvV2) { }
@RequestMapping(value={""}) public String page(Model model, Page<Blog> page, BlogQuery blogQuery, HttpSession httpSession) { return (String)delegate$b310fa0.intercept(this, new Object[]{model, page, blogQuery, httpSession}, (Callable<?>)new auxiliary.ADTaVnew(this, model, page, blogQuery, httpSession), cachedValue$CYumwYK8$7jqr912); }
......
final /* synthetic */ Object delete$original$PYp487Vn$accessor$CYumwYK8(Long l) { return this.delete$original$PYp487Vn(l); }}
Affect(row-cnt:9) cost in 1594 ms.[arthas@1]$复制代码
7、sc（查看已经加载的类）
[arthas@1]$ sc -d com.jt.blog.controller.BackBlogController class-info com.jt.blog.controller.BackBlogController code-source /apache-tomcat-8.5.9/webapps/ROOT/WEB-INF/classes/ name com.jt.blog.controller.BackBlogController isInterface false isAnnotation false isEnum false isAnonymousClass false isArray false isLocalClass false isMemberClass false isPrimitive false isSynthetic false simple-name BackBlogController modifier public ...... classLoaderHash 15101d33
Affect(row-cnt:2) cost in 48 ms.[arthas@1]$
复制代码
8、sm（列出某个类加载的方法）
[arthas@1]$ sm com.jt.blog.controller.BackBlogControllercom.jt.blog.controller.BackBlogController$$EnhancerBySpringCGLIB$$d6e1bd41 <init>()Vcom.jt.blog.controller.BackBlogController$$EnhancerBySpringCGLIB$$d6e1bd41 page(Lorg/springframework/ui/Model;Lcom/jt/blog/common/model/Page;Lcom/jt/blog/vo/BlogQuery;Ljavax/servlet/http/HttpSession;)Ljava/lang/String;......Affect(row-cnt:73) cost in 17 ms.[arthas@1]$复制代码
9、trace（跟踪方法的消耗时间）
我们可以使用 trace 命令来查找最耗时的方法，在此过程中需要知道包名、类名，以及方法的名字。
[arthas@1]$ trace com.jt.blog.controller.BackBlogController$$EnhancerBySpringCGLIB$$d6e1bd41 pagePress Q or Ctrl+C to abort.Affect(class-cnt:1 , method-cnt:1) cost in 235 ms.`---ts=2020-03-07 00:40:01;thread_name=http-nio-8080-exec-167;id=662;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@15101d33 `---[91.777786ms] com.jt.blog.controller.BackBlogController$$EnhancerBySpringCGLIB$$d6e1bd41:page() `---[91.101545ms] org.springframework.cglib.proxy.MethodInterceptor:intercept() #0
`---ts=2020-03-07 00:40:02;thread_name=http-nio-8080-exec-166;id=661;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@15101d33 `---[58.901494ms] com.jt.blog.controller.BackBlogController$$EnhancerBySpringCGLIB$$d6e1bd41:page() `---[58.727281ms] org.springframework.cglib.proxy.MethodInterceptor:intercept() #0
`---ts=2020-03-07 00:40:02;thread_name=http-nio-8080-exec-150;id=63b;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@15101d33 `---[93.064632ms] com.jt.blog.controller.BackBlogController$$EnhancerBySpringCGLIB$$d6e1bd41:page() `---[92.902346ms] org.springframework.cglib.proxy.MethodInterceptor:intercept() #0......
[arthas@1]$ trace tk.mybatis.mapper.common.Mapper insertPress Q or Ctrl+C to abort.Affect(class-cnt:5 , method-cnt:5) cost in 538 ms.`---ts=2020-03-07 00:59:22;thread_name=http-nio-8080-exec-172;id=671;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@15101d33 `---[2.938966ms] com.sun.proxy.$Proxy90:insert()
`---ts=2020-03-07 00:59:22;thread_name=http-nio-8080-exec-172;id=671;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@15101d33 `---[0.895433ms] com.sun.proxy.$Proxy93:insert()
`---ts=2020-03-07 00:59:24;thread_name=http-nio-8080-exec-150;id=63b;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@15101d33 `---[2.156481ms] com.sun.proxy.$Proxy90:insert()复制代码
[arthas@1]$ trace com.jt.blog.service.BlogReadServiceImpl pagePress Q or Ctrl+C to abort.Affect(class-cnt:1 , method-cnt:1) cost in 371 ms.`---ts=2020-03-07 01:04:44;thread_name=http-nio-8080-exec-6;id=32;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@3d0c8d44 `---[75.94035ms] com.jt.blog.service.BlogReadServiceImpl:page() +---[0.034707ms] com.jt.blog.common.model.Response:<init>() #34 +---[0.019337ms] com.jt.blog.common.model.Page:getPageNo() #36 +---[0.01106ms] com.jt.blog.common.model.Page:getPageSize() #36 +---[4.590002ms] com.github.pagehelper.PageHelper:startPage() #36 +---[0.542359ms] tk.mybatis.mapper.entity.Example:<init>() #37 +---[0.070315ms] tk.mybatis.mapper.entity.Example:createCriteria() #38 +---[0.037231ms] com.jt.blog.vo.BlogQuery:getCategoryId() #40 +---[0.007289ms] com.jt.blog.vo.BlogQuery:getBeginTime() #43 +---[0.007167ms] com.jt.blog.vo.BlogQuery:getPersonal() #46 +---[0.006318ms] com.jt.blog.vo.BlogQuery:getPersonal() #47 +---[0.009675ms] tk.mybatis.mapper.entity.Example$Criteria:andEqualTo() #47 +---[30.90447ms] tk.mybatis.mapper.common.Mapper:selectByExample() #50 +---[36.179664ms] com.jt.blog.service.BlogReadServiceImpl:wrapBlogStatistics() #51 [throws Exception] +---[0.785948ms] com.google.common.base.Throwables:getStackTraceAsString() #58 +---[0.522234ms] org.slf4j.Logger:error() #58 `---[0.030388ms] com.jt.blog.common.model.Response:setError() #59
`---ts=2020-03-07 01:04:44;thread_name=http-nio-8080-exec-10;id=3c;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@3d0c8d44 `---[94.699363ms] com.jt.blog.service.BlogReadServiceImpl:page() +---[0.009802ms] com.jt.blog.common.model.Response:<init>() #34 +---[0.007825ms] com.jt.blog.common.model.Page:getPageNo() #36 ......复制代码
我们可以看到 page 方法总耗时 75.94035 ms：
selectByExample 调用耗时 30.90447 ms；
wrapBlogStatistics 调用耗时 36.179664 ms；
startPage 调用耗时 4.590002 ms。
selectByExample 和 wrapBlogStatistics 方法耗时比较长，能够定位到方法级别的消耗时长时，就找到慢的原因了。
10、stack （查看某方法的调用栈）
[arthas@1]$ stack tk.mybatis.mapper.common.Mapper insertPress Q or Ctrl+C to abort.Affect(class-cnt:5 , method-cnt:5) cost in 561 ms.ts=2020-03-07 01:00:51;thread_name=http-nio-8080-exec-171;id=66f;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@15101d33 @com.jt.blog.service.BlogWriteServiceImpl.create() at sun.reflect.GeneratedMethodAccessor255.invoke(null:-1) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:302) at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ......
ts=2020-03-07 01:00:51;thread_name=http-nio-8080-exec-171;id=66f;is_daemon=true;priority=5;TCCL=org.apache.catalina.loader.ParallelWebappClassLoader@15101d33 @com.jt.blog.service.BlogWriteServiceImpl.create() at sun.reflect.GeneratedMethodAccessor255.invoke(null:-1) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) ......
[arthas@1]$复制代码
11、classloader（查看 classloader 的继承树，urls，类加载信息）
[arthas@1]$ classloader name numberOfInstances loadedCountTotal org.apache.catalina.loader.ParallelWebappClassLoader 2 6680 BootstrapClassLoader 1 3836 sun.misc.Launcher$AppClassLoader 1 3029 com.taobao.arthas.agent.ArthasClassloader 1 1194 java.net.URLClassLoader 1 860 org.apache.skywalking.apm.agent.core.plugin.loader.AgentClassLoader 3 306 sun.reflect.DelegatingClassLoader 289 289 sun.misc.Launcher$ExtClassLoader 1 13 javax.management.remote.rmi.NoCallStackClassLoader 2 2Affect(row-cnt:9) cost in 36 ms.[arthas@1]$复制代码
12、monitor （监控方法）
[arthas@1]$ monitor -h USAGE: monitor [-c <value>] [-h] [-n <value>] [-E <value>] class-pattern method-pattern
SUMMARY: Monitor method execution statistics, e.g. total/success/failure count, average rt, fail rate, etc.
Examples: monitor org.apache.commons.lang.StringUtils isBlank monitor org.apache.commons.lang.StringUtils isBlank -c 5 monitor -E org\.apache\.commons\.lang\.StringUtils isBlank
WIKI: https://alibaba.github.io/arthas/monitor
OPTIONS: -c, --cycle <value> The monitor interval (in seconds), 60 seconds by default -h, --help this help -n, --limits <value> Threshold of execution times -E, --regex <value> Enable regular expression to match (wildcard matching by default) <class-pattern> Path and classname of Pattern Matching <method-pattern> Method of Pattern Matching
[arthas@1]$复制代码
示例：
[arthas@1]$ monitor tk.mybatis.mapper.common.Mapper insertPress Q or Ctrl+C to abort.Affect(class-cnt:5 , method-cnt:5) cost in 411 ms. timestamp class method total success fail avg-rt(ms) fail-rat e------------------------------------------------------------------------------------------------- 2020-03-07 01:11:38 com.sun.proxy.$Proxy93 insert 197 197 0 1.67 0.00% 2020-03-07 01:11:38 com.sun.proxy.$Proxy90 insert 197 197 0 3.39 0.00%复制代码
七、总结
在本文我主要介绍了 Arthas 是什么、为什么使用 Arthas，以及通过实际操作演示 Arthas 常用命令是如何使用的的，操作实例都是比较典型的排查线上问题的方式，通过实例的演示也能看出来 Arthas 的强大和便捷性。
划线
评论
复制
发布于: 刚刚阅读数: 3
版权声明: 本文为 InfoQ 作者【zuozewei】的原创文章。
原文链接:【http://xie.infoq.cn/article/050dbef942aa7af428dbf88f1】。
本文遵守【CC-BY 4.0】协议，转载请保留原文出处及本版权声明。
zuozewei
关注
测试及性能 | 公众号@7DGroup 2017.12.23 加入
CSDN博客专家、测试领域优质创作者，华为云云享专家、2021年度华为云社区十佳博主，掘金2021年度人气作者No.12，极客时间《全链路压测实战30讲》专栏作者之一，《性能测试实战30讲》《高楼的性能工程实战课》编委。
评论