什么是 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 自动补全功能，进一步方便进行问题的定位和诊断。
快速安装
前提条件
[root@c41287379b7c /]# yum install telnet
[root@c41287379b7c /]# yum install unzip
一键安装
使用命令下载 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 Speed
100 961 100 961 0 0 743 0 0:00:01 0:00:01 --:--:-- 743
downloading... ./as.sh.1598
Arthas install successed.
使用命令下载 Arthas jar包：
curl -O https://arthas.aliyun.com/arthas-boot.jar
java -jar arthas-boot.jar
Arthas 提供是 jar 包形式，其本质是个 Java 应用。
快速使用
启动脚本并连接进程
使用脚本快速启动：
[root@c41287379b7c /]# ./as.sh
Arthas script version: 3.1.7
[INFO] JAVA_HOME: /usr/jdk1.8.0_111
Found existing java process, please choose one and hit RETURN.
* [1]: 1 org.apache.catalina.startup.Bootstrap
1 //这里输入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.jar
update completed.
Arthas home: /root/.arthas/lib/3.1.7/arthas
Calculating attach execution time...
Attaching to 1 using version /root/.arthas/lib/3.1.7/arthas...
real 0m2.298s
user 0m0.302s
sys 0m0.145s
Attach success.
telnet connecting to arthas server... current timestamp is 1583537651
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
,---. ,------. ,--------.,--. ,--. ,---. ,---.
/ O \ | .--. ''--. .--'| '--' | / O \ ' .-'
| .-. || '--'.' | | | .--. || .-. |`. `-.
| | | || |\ \ | | | | | || | | |.-' |
`--' `--'`--' '--' `--' `--' `--'`--' `--'`-----'
wiki https://alibaba.github.io/arthas
tutorials https://alibaba.github.io/arthas/arthas-tutorials
version 3.1.7
pid 1
time 2020-03-06 23:34:10
[arthas@1]$
启动 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/doc
version: 3.0.5.20181127201536
pid: 71560
time: 2020-11-28 19:16:24
$
出现 Arthas Logo 之后便可以正常使用了。
使用示例
dashboard（当前系统的实时数据面板）
ID NAME GROUP PRIORITY STATE %CPU TIME INTERRUPTE DAEMON
1572 http-nio-8080-exec-139 main 5 TIMED_WAITI 18 0:12 false true
1561 http-nio-8080-exec-138 main 5 RUNNABLE 17 0:18 false true
1539 http-nio-8080-exec-131 main 5 TIMED_WAITI 10 1:17 false true
1575 http-nio-8080-exec-141 main 5 TIMED_WAITI 10 0:0 false true
1573 http-nio-8080-exec-140 main 5 TIMED_WAITI 9 0:8 false true
1559 http-nio-8080-exec-136 main 5 TIMED_WAITI 8 0:29 false true
1558 grpc-default-executor-1340 main 5 TIMED_WAITI 4 0:5 false true
28 grpc-default-worker-ELG-1-4 main 5 RUNNABLE 4 6:44 false true
1560 http-nio-8080-exec-137 main 5 RUNNABLE 4 0:23 false true
Memory used total max usage GC
heap 155M 311M 843M 18.47% gc.ps_scavenge.count 6631
ps_eden_space 39M 171M 310M 12.72% gc.ps_scavenge.time(ms) 52792
ps_survivor_space 1M 2M 2M 90.63% gc.ps_marksweep.count 21
ps_old_gen 114M 138M 632M 18.10% gc.ps_marksweep.time(ms) 11572
Runtime
os.name Linux
os.version 3.10.0-1062.9.1.el7.x86_64
java.version 1.8.0_111
java.home /usr/jdk1.8.0_111/jre
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.hostname
java.rmi.server.hostname=106.54.17.234
[arthas@1]$ sysprop file.encoding
file.encoding=ANSI_X3.4-1968
[arthas@1]$
//修改属性
[arthas@1]$ sysprop user.country
user.country=US
[arthas@1]$ sysprop user.country CN
Successfully changed the system property.
user.country=CN
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
thread（查看线程）
//查看所有线程
[arthas@1]$ thread
Threads Total: 59, NEW: 0, RUNNABLE: 24, BLOCKED: 0, WAITING: 9, TIMED_WAITING: 26, TERMINATED: 0
ID NAME GROUP PRIORIT STATE %CPU TIME INTERRU DAEMON
1572 http-nio-8080-exec-139 main 5 TIMED_W 17 1:32 false true
1597 http-nio-8080-exec-151 main 5 RUNNABL 15 0:10 false true
1539 http-nio-8080-exec-131 main 5 TIMED_W 11 2:37 false true
1591 http-nio-8080-exec-148 main 5 RUNNABL 11 0:23 false true
1587 http-nio-8080-exec-146 main 5 TIMED_W 9 0:33 false true
1585 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]$
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]$
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 BackBlogController
implements 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]$
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]$
sm（列出某个类加载的方法）
[arthas@1]$ sm com.jt.blog.controller.BackBlogController
com.jt.blog.controller.BackBlogController$$EnhancerBySpringCGLIB$$d6e1bd41 <init>()V
com.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]$
trace（跟踪方法的消耗时间）
我们可以使用 trace 命令来查找最耗时的方法，在此过程中需要知道包名、类名，以及方法的名字。
[arthas@1]$ trace com.jt.blog.controller.BackBlogController$$EnhancerBySpringCGLIB$$d6e1bd41 page
Press 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 insert
Press 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 page
Press 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 方法耗时比较长，能够定位到方法级别的消耗时长时，就找到慢的原因了。
stack （查看某方法的调用栈）
[arthas@1]$ stack tk.mybatis.mapper.common.Mapper insert
Press 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]$
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 2
Affect(row-cnt:9) cost in 36 ms.
[arthas@1]$
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 insert
Press 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 的强大和便捷性。