[Java知识库]一文带你快速了解 Java 线上问题快速诊断神器 Arthas

一、什么是 Arthas

Arthas 是 Alibaba开源的一款 Java 诊断工具，能够查看 Java 应用的线程状态、JVM 信息等，支持在线对业务问题诊断，比如查看方法调用的出入参、执行过程、抛出的异常、输出方法执行耗时等，大大提升了线上问题的排查效率。

官网：https://arthas.aliyun.com/zh-cn/

二、特性一览

三、Arthas 能为你做什么？

你遇到以下类似问题而束手无策时，Arthas可以帮助你解决：

1. 这个类从哪个 jar 包加载的？为什么会报各种类相关的 Exception？
2. 我改的代码为什么没有执行到？难道是我没 commit？分支搞错了？
3. 遇到问题无法在线上 debug，难道只能通过加日志再重新发布吗？
4. 线上遇到某个用户的数据处理有问题，但线上同样无法 debug，线下无法重现！
5. 是否有一个全局视角来查看系统的运行状况？
6. 有什么办法可以监控到JVM的实时运行状态？
7. 怎么快速定位应用的热点，生成火焰图？
8. 怎样直接从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  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 应用。
?

五、快速使用

1、启动脚本并连接进程

使用脚本快速启动：

[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]$

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/doc
version: 3.0.5.20181127201536
pid: 71560
time: 2020-11-28 19:16:24
 
$

出现 Arthas Logo 之后便可以正常使用了。

六、使用示例

1、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

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.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

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]$ 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]$

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 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]$

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.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]$

9、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 方法耗时比较长，能够定位到方法级别的消耗时长时，就找到慢的原因了。

10、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]$

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                  2
Affect(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 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 的强大和便捷性。