Arthas实践 - 如何快速排查线上问题

时间 2020-01-06

标签 arthas 实践如何快速排查线上问题繁體版

原文原文链接

此处再也不赘述Arthas的安装，直接上使用技巧html

官网地址: https://alibaba.github.io/arthas/前端

1. 查看线程信息java

threadgit

查看当前线程信息，查看线程的堆栈github

参数说明web

参数名称	参数说明
id	线程id
[n:]	指定最忙的前N个线程并打印堆栈
[b]	找出当前阻塞其余线程的线程
[i `<value>`]	指定cpu占比统计的采样间隔，单位为毫秒

1) 查看当前全部线程正则表达式

thread

输出spring

2) 查看当前最忙的前n个线程并打印堆栈express

thread -n 2

输出apache

$ thread -n 2
"http-nio-8080-exec-1" Id=147 cpuUsage=18% TIMED_WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@48a1d8fc
    at sun.misc.Unsafe.park(Native Method)
    -  waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@48a1d8fc
    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:1073)
    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)


"http-nio-8080-exec-25" Id=180 cpuUsage=18% TIMED_WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@48a1d8fc
    at sun.misc.Unsafe.park(Native Method)
    -  waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@48a1d8fc
    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:1073)
    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)

3) 显示指定id线程的运行堆栈

thread 180

输出

$ thread 180
"http-nio-8080-exec-25" Id=180 TIMED_WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@48a1d8fc
    at sun.misc.Unsafe.park(Native Method)
    -  waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@48a1d8fc
    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:1073)
    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)

4) 找出阻塞其余线程的线程

thread -b

输出

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

注意，目前只支持找出synchronized关键字阻塞住的线程，若是是java.util.concurrent.Lock，目前还不支持。

2. 反编译已加载类的源码

反编译指定已加载类的源码

jad 命令将 JVM 中实际运行的 class 的 byte code 反编译成 java 代码，便于你理解业务逻辑；

在 Arthas Console 上，反编译出来的源码是带语法高亮的，阅读更方便
固然，反编译出来的 java 代码可能会存在语法错误，但不影响你进行阅读理解

参数说明

参数名称	参数说明
class-pattern	类名表达式匹配
`[c:]`	类所属 ClassLoader 的 hashcode
[E]	开启正则表达式匹配，默认为通配符匹配

1) 直接反编译查看源码

jad com.esell.*.DeviceAdSweepCodeController

输出

$ jad com.esell.*.DeviceAdSweepCodeController

ClassLoader:                                                                                                                                                                                                  
+-org.springframework.boot.loader.LaunchedURLClassLoader@7c75222b                                                                                                                                             
  +-sun.misc.Launcher$AppClassLoader@18b4aac2                                                                                                                                                                 
    +-sun.misc.Launcher$ExtClassLoader@317e9c3c                                                                                                                                                               

Location:                                                                                                                                                                                                     
file:/home/admin/app/c4237202-afae-4d8b-9dad-e788cb42d7fb/es-yxfbp-main-1.0.0.jar!/BOOT-INF/lib/es-yxfbp-gw-1.0.0-SNAPSHOT.jar!/                                                                              

/*
 * Decompiled with CFR 0_132.
 * 
 * Could not load the following classes:
 *  cn.hutool.core.thread.ThreadUtil
 *  com.alibaba.fastjson.JSONObject
 *  com.esell.annotation.RequestParameter
 *  com.esell.annotation.Validation
 *  com.esell.message.domestic.SimpleApiRequest
 *  com.esell.v2.device.controller.DeviceAdSweepCodeController$1
 *  com.esell.v2.device.model.dto.DeviceAdSweepCodeDto
 *  com.esell.v2.device.service.DeviceAdSweepCodeService
 *  javax.servlet.http.HttpServletResponse
 *  org.slf4j.Logger
 *  org.slf4j.LoggerFactory
 *  org.springframework.beans.factory.annotation.Autowired
 *  org.springframework.web.bind.annotation.GetMapping
 *  org.springframework.web.bind.annotation.RequestMapping
 *  org.springframework.web.bind.annotation.RestController
 */
package com.esell.v2.device.controller;

import cn.hutool.core.thread.ThreadUtil;
import com.alibaba.fastjson.JSONObject;
import com.esell.annotation.RequestParameter;
import com.esell.annotation.Validation;
import com.esell.message.domestic.SimpleApiRequest;
import com.esell.v2.device.controller.DeviceAdSweepCodeController;
import com.esell.v2.device.model.dto.DeviceAdSweepCodeDto;
import com.esell.v2.device.service.DeviceAdSweepCodeService;
import java.io.IOException;
import javax.servlet.http.HttpServletResponse;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
@RequestMapping(value={"/device/ad/sweep"})
public class DeviceAdSweepCodeController {
    private static final Logger log = LoggerFactory.getLogger(DeviceAdSweepCodeController.class);
    @Autowired
    private DeviceAdSweepCodeService deviceAdSweepCodeService;

    @GetMapping(value={"/add.shtml"})
    @Validation(value={"$.deviceUuid,required,\u8bbe\u5907\u7f16\u53f7\u4e0d\u80fd\u4e3a\u7a7a", "$.adId,required,\u5e7f\u544a\u7f16\u53f7\u4e0d\u80fd\u4e3a\u7a7a", "$.redirect,required,\u8f6c\u53d1\u5730\u5740\u4e0d\u80fd\u4e3a\u7a7a"})
    public void sweep(@RequestParameter SimpleApiRequest apiRequest, HttpServletResponse response) throws IOException {
        JSONObject jsonObject = new JSONObject();
        DeviceAdSweepCodeDto reqData = (DeviceAdSweepCodeDto)((JSONObject)apiRequest.getPayload()).toJavaObject(DeviceAdSweepCodeDto.class);
        ThreadUtil.execute((Runnable)new /* Unavailable Anonymous Inner Class!! */);
        response.sendRedirect(reqData.getRedirect());
    }

    static /* synthetic */ DeviceAdSweepCodeService access$000(DeviceAdSweepCodeController x0) {
        return x0.deviceAdSweepCodeService;
    }

    static /* synthetic */ Logger access$100() {
        return log;
    }
}

Affect(row-cnt:1) cost in 544 ms.

2) 反编绎时只显示源代码

默认状况下，反编译结果里会带有ClassLoader信息，经过--source-only选项，能够只打印源代码。

jad --source-only com.esell.*.DeviceAdSweepCodeController

输出

/*
 * Decompiled with CFR 0_132.
 * 
 * Could not load the following classes:
 *  cn.hutool.core.thread.ThreadUtil
 *  com.alibaba.fastjson.JSONObject
 *  com.esell.annotation.RequestParameter
 *  com.esell.annotation.Validation
 *  com.esell.message.domestic.SimpleApiRequest
 *  com.esell.v2.device.controller.DeviceAdSweepCodeController$1
 *  com.esell.v2.device.model.dto.DeviceAdSweepCodeDto
 *  com.esell.v2.device.service.DeviceAdSweepCodeService
 *  javax.servlet.http.HttpServletResponse
 *  org.slf4j.Logger
 *  org.slf4j.LoggerFactory
 *  org.springframework.beans.factory.annotation.Autowired
 *  org.springframework.web.bind.annotation.GetMapping
 *  org.springframework.web.bind.annotation.RequestMapping
 *  org.springframework.web.bind.annotation.RestController
 */
package com.esell.v2.device.controller;

import cn.hutool.core.thread.ThreadUtil;
import com.alibaba.fastjson.JSONObject;
import com.esell.annotation.RequestParameter;
import com.esell.annotation.Validation;
import com.esell.message.domestic.SimpleApiRequest;
import com.esell.v2.device.controller.DeviceAdSweepCodeController;
import com.esell.v2.device.model.dto.DeviceAdSweepCodeDto;
import com.esell.v2.device.service.DeviceAdSweepCodeService;
import java.io.IOException;
import javax.servlet.http.HttpServletResponse;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
@RequestMapping(value={"/device/ad/sweep"})
public class DeviceAdSweepCodeController {
    private static final Logger log = LoggerFactory.getLogger(DeviceAdSweepCodeController.class);
    @Autowired
    private DeviceAdSweepCodeService deviceAdSweepCodeService;

    @GetMapping(value={"/add.shtml"})
    @Validation(value={"$.deviceUuid,required,\u8bbe\u5907\u7f16\u53f7\u4e0d\u80fd\u4e3a\u7a7a", "$.adId,required,\u5e7f\u544a\u7f16\u53f7\u4e0d\u80fd\u4e3a\u7a7a", "$.redirect,required,\u8f6c\u53d1\u5730\u5740\u4e0d\u80fd\u4e3a\u7a7a"})
    public void sweep(@RequestParameter SimpleApiRequest apiRequest, HttpServletResponse response) throws IOException {
        JSONObject jsonObject = new JSONObject();
        DeviceAdSweepCodeDto reqData = (DeviceAdSweepCodeDto)((JSONObject)apiRequest.getPayload()).toJavaObject(DeviceAdSweepCodeDto.class);
        ThreadUtil.execute((Runnable)new /* Unavailable Anonymous Inner Class!! */);
        response.sendRedirect(reqData.getRedirect());
    }

    static /* synthetic */ DeviceAdSweepCodeService access$000(DeviceAdSweepCodeController x0) {
        return x0.deviceAdSweepCodeService;
    }

    static /* synthetic */ Logger access$100() {
        return log;
    }
}

3) 反编绎时指定方法

jad com.esell.*.DeviceAdSweepCodeController sweep

输出

$ jad com.esell.*.DeviceAdSweepCodeController sweep

ClassLoader:                                                                                                                                                                                                  
+-org.springframework.boot.loader.LaunchedURLClassLoader@7c75222b                                                                                                                                             
  +-sun.misc.Launcher$AppClassLoader@18b4aac2                                                                                                                                                                 
    +-sun.misc.Launcher$ExtClassLoader@317e9c3c                                                                                                                                                               

Location:                                                                                                                                                                                                     
file:/home/admin/app/c4237202-afae-4d8b-9dad-e788cb42d7fb/es-yxfbp-main-1.0.0.jar!/BOOT-INF/lib/es-yxfbp-gw-1.0.0-SNAPSHOT.jar!/                                                                              

@GetMapping(value={"/add.shtml"})
@Validation(value={"$.deviceUuid,required,\u8bbe\u5907\u7f16\u53f7\u4e0d\u80fd\u4e3a\u7a7a", "$.adId,required,\u5e7f\u544a\u7f16\u53f7\u4e0d\u80fd\u4e3a\u7a7a", "$.redirect,required,\u8f6c\u53d1\u5730\u5740\u4e0d\u80fd\u4e3a\u7a7a"})
public void sweep(@RequestParameter SimpleApiRequest apiRequest, HttpServletResponse response) throws IOException {
    JSONObject jsonObject = new JSONObject();
    DeviceAdSweepCodeDto reqData = (DeviceAdSweepCodeDto)((JSONObject)apiRequest.getPayload()).toJavaObject(DeviceAdSweepCodeDto.class);
    ThreadUtil.execute((Runnable)new /* Unavailable Anonymous Inner Class!! */);
    response.sendRedirect(reqData.getRedirect());
}

Affect(row-cnt:1) cost in 354 ms.

4) 反编绎时指定classloader

当有多个 ClassLoader 都加载了这个类时，jad 命令会输出对应 ClassLoader 实例的 hashcode，而后你只须要从新执行 jad 命令，并使用参数 -c 就能够反编译指定 ClassLoader 加载的那个类了；以下

$ jad *DeviceAdSweepCodeController

 Found more than one class for: *DeviceAdSweepCodeController, Please use jad -c <hashcode> *DeviceAdSweepCodeController                                                                                                                                                                
 HASHCODE  CLASSLOADER                                                                                                                                                                                        
 7c75222b  +-org.springframework.boot.loader.LaunchedURLClassLoader@7c75222b                                                                                                                                  
             +-sun.misc.Launcher$AppClassLoader@18b4aac2                                                                                                                                                      
               +-sun.misc.Launcher$ExtClassLoader@317e9c3c                                                                                                                                                    
 7c75222b  +-org.springframework.boot.loader.LaunchedURLClassLoader@7c75222b                                                                                                                                  
             +-sun.misc.Launcher$AppClassLoader@18b4aac2                                                                                                                                                      
               +-sun.misc.Launcher$ExtClassLoader@317e9c3c                                                                                                                                                    

Affect(row-cnt:0) cost in 24 ms.

使用-c便可进入相应的源码查看

jad -c 7c75222b *DeviceAdSweepCodeController

5) 反编绎输出到指定目录

须要使用--source-only

jad --source-only com.esell.gw.yxfbp.rew.adv.controller.AdvController > /usr/local/arthas/file/AdvController.java

3. 使用Arthas进行线上热更新

redefine

加载外部的.class文件，redefine jvm已加载的类。

参数说明

参数名称	参数说明
[c:]	ClassLoader的hashcode
[p:]	外部的`.class`文件的完整路径，支持多个

1) 热部署class文件

首先在本地将须要热更新的java文件编译成class文件，上传到服务器，在arthas进程中执行如下命令

redefine /usr/local/arthas/file/AdvController.class

输出以下语句则为热更新成功

要肯定更改内容是否已经部署到服务器，可采用反编译命令获取源文件查看

jad --source-only com.esell.gw.yxfbp.rew.adv.controller.AdvController > /usr/local/arthas/file/AdvController.java

下载后经过 vi AdvController.java查看，在命令模式下使用 /字符串 查看对应内容，按下小写n，向下查找，按下大写N，向上查找

重点提醒

redefine的限制

不容许新增长field/method
正在跑的函数，没有退出不能生效，好比下面新增长的System.out.println，只有run()函数里的会生效

public class MathGame {
    public static void main(String[] args) throws InterruptedException {
        MathGame game = new MathGame();
        while (true) {
            game.run();
            TimeUnit.SECONDS.sleep(1);
            // 这个不生效，由于代码一直跑在 while里
            System.out.println("in loop");
        }
    }

    public void run() throws InterruptedException {
        // 这个生效，由于run()函数每次均可以完整结束
        System.out.println("call run()");
        try {
            int number = random.nextInt();
            List<Integer> primeFactors = primeFactors(number);
            print(number, primeFactors);

        } catch (Exception e) {
            System.out.println(String.format("illegalArgumentCount:%3d, ", illegalArgumentCount) + e.getMessage());
        }
    }

4. 对方法的调用进行性能监控

方法执行监控

对匹配 class-pattern／method-pattern的类、方法的调用进行监控。

monitor 命令是一个非实时返回命令.

实时返回命令是输入以后当即返回，而非实时返回的命令，则是不断的等待目标 Java 进程返回信息，直到用户输入 Ctrl+C 为止。

服务端是以任务的形式在后台跑任务，植入的代码随着任务的停止而不会被执行，因此任务关闭后，不会对原有性能产生太大影响，并且原则上，任何Arthas命令不会引发原有业务逻辑的改变。

监控的维度说明

监控项	说明
timestamp	时间戳
class	Java类
method	方法（构造方法、普通方法）
total	调用次数
success	成功次数
fail	失败次数
rt	平均RT
fail-rate	失败率

参数说明

方法拥有一个命名参数 [c:]，意思是统计周期（cycle of output），拥有一个整型的参数值

参数名称	参数说明
class-pattern	类名表达式匹配
method-pattern	方法名表达式匹配
[E]	开启正则表达式匹配，默认为通配符匹配
`[c:]`	统计周期，默认值为120秒

1) 对方法在指定周期内的调用进行性能监控

monitor -c 10 com.esell.v2.device.controller.DeviceBaseController listDevice

输出

2) 对多个方法在指定周期的调用进行性能监控

须要注意的是此处只能使用全类名而不能使用通配符

monitor -c 10 -E com.esell.v2.device.controller.DeviceBaseController|com.esell.v2.template.controller.TemplateV2Controller listDevice|search

输出

5. 查看方法中每一个节点的耗时

trace

方法内部调用路径，并输出方法路径上的每一个节点上耗时

trace 命令能主动搜索 class-pattern／method-pattern(可以使用通配符) 对应的方法调用路径，渲染和统计整个调用链路上的全部性能开销和追踪调用链路。

参数说明

参数名称	参数说明
class-pattern	类名表达式匹配
method-pattern	方法名表达式匹配
condition-express	条件表达式
[E]	开启正则表达式匹配，默认为通配符匹配
`[n:]`	命令执行次数
`#cost`	方法执行耗时

首先须要使用arthas进入相应的jvm进程

1) 查看到方法各节点的耗时

使用 trace 类名方法 在客户端访问此方法便可

trace com.esell.gw.yxfbp.iot.manage.PublishManager updateAd

或

trace *PublishManager updateAd

输出能够看到方法的总耗时，以及每一个节点的耗时

$ trace com.esell.gw.yxfbp.iot.manage.PublishManager updateAd
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 279 ms.
`---ts=2019-07-23 10:44:44;thread_name=http-nio-8080-exec-3;id=a1;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@211d9483
    `---[19562.263654ms] com.esell.gw.yxfbp.iot.manage.PublishManager:updateAd()
        +---[0.023008ms] java.lang.Integer:intValue() #76
        +---[7.961462ms] com.esell.gw.yxfbp.rew.adDisplay.mapper.AdDisplayMapper:selectDeviceIdsByAdId() #78
        +---[0.015249ms] org.apache.commons.collections4.CollectionUtils:isNotEmpty() #79
        +---[42.933313ms] com.esell.v2.device.dao.DeviceBaseDao:listUuidById() #80
        `---[19508.385811ms] java.util.List:forEach() #81

2) 过滤掉jvm函数的耗时

使用 trace 类名方法 -j 加入 -j 参数过滤掉jvm函数

trace com.esell.gw.yxfbp.iot.manage.PublishManager updateAd -j

输出

$ trace com.esell.gw.yxfbp.iot.manage.PublishManager updateAd -j
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 206 ms.
`---ts=2019-07-23 10:48:38;thread_name=http-nio-8080-exec-20;id=bb;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@211d9483
    `---[16762.507405ms] com.esell.gw.yxfbp.iot.manage.PublishManager:updateAd()
        +---[3.685484ms] com.esell.gw.yxfbp.rew.adDisplay.mapper.AdDisplayMapper:selectDeviceIdsByAdId() #78
        +---[0.013117ms] org.apache.commons.collections4.CollectionUtils:isNotEmpty() #79
        `---[26.934144ms] com.esell.v2.device.dao.DeviceBaseDao:listUuidById() #8

3) 对多个类的多个方法进行追踪

使用 trace -E 类名|全类名方法|方法 加入 -E 来对多个类的多个方法进行追踪，注意此处不能使用通配符

trace -E com.esell.gw.yxfbp.iot.manage.PublishManager|com.esell.v2.device.controller.DeviceBaseController updateAd|listDevice

输出

$ trace -E com.esell.gw.yxfbp.iot.manage.PublishManager|com.esell.v2.device.controller.DeviceBaseController updateAd|listDevice
Press Q or Ctrl+C to abort.
Affect(class-cnt:2 , method-cnt:2) cost in 511 ms.
`---ts=2019-07-23 11:45:21;thread_name=http-nio-8080-exec-54;id=dd;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@211d9483
    `---[15607.698171ms] com.esell.gw.yxfbp.iot.manage.PublishManager:updateAd()
        +---[0.020851ms] java.lang.Integer:intValue() #76
        +---[3.550901ms] com.esell.gw.yxfbp.rew.adDisplay.mapper.AdDisplayMapper:selectDeviceIdsByAdId() #78
        +---[0.014086ms] org.apache.commons.collections4.CollectionUtils:isNotEmpty() #79
        +---[16.370718ms] com.esell.v2.device.dao.DeviceBaseDao:listUuidById() #80
        `---[15586.764431ms] java.util.List:forEach() #81

`---ts=2019-07-23 11:45:40;thread_name=http-nio-8080-exec-56;id=df;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@211d9483
    `---[249.902613ms] com.esell.v2.device.controller.DeviceBaseController:listDevice()
        +---[3.444852ms] com.esell.yxf.common.util.LoggerMainBuilderUtils:requestLog() #230
        +---[0.011863ms] com.esell.message.SimpleApiRequest:getPayload() #234
        +---[0.054789ms] com.alibaba.fastjson.JSONObject:toJavaObject() #234
        +---[0.064045ms] com.esell.v2.device.model.dto.DeviceBaseSearchDto:copyNew() #234
        +---[0.00505ms] com.esell.message.SimpleApiRequest:getString() #235
        +---[0.036919ms] java.lang.String:replaceAll() #236
        +---[0.002666ms] com.esell.v2.device.model.dto.DeviceBaseSearchDto:setSortField() #237
        +---[1.288203ms] com.esell.util.SessionUtils:findUser() #240
        +---[0.007632ms] com.esell.api.account.bean.AccountBean:getCrmCode() #241
        +---[0.0048ms] com.esell.v2.device.model.dto.DeviceBaseSearchDto:setCrmCode() #241
        +---[0.0156ms] com.esell.api.account.bean.type.AccountUtils:remitCheckPermission() #244
        +---[0.003174ms] com.esell.v2.device.model.dto.DeviceBaseSearchDto:getNotBind() #253
        +---[200.227842ms] com.esell.v2.device.service.DeviceBaseService:search() #265
        +---[0.021341ms] com.esell.spring.boot.starter.mybatis.plugin.pagination.PaginationBean:getData() #267
        +---[0.011263ms] com.esell.message.SimpleApiRequest:getArray() #270
        +---[0.006812ms] java.util.ArrayList:<init>() #271
        +---[0.004011ms] com.esell.util.SessionUtils:current() #272
        +---[0.008421ms] com.esell.session.Session:getLanguage() #272
        +---[0.030655ms] java.util.Optional:ofNullable() #273
        +---[0.032682ms] java.util.Collections:emptyList() #273
        +---[0.007926ms] java.util.Optional:orElse() #273
        +---[0.052993ms] java.util.List:forEach() #273
        +---[42.130235ms] java.util.List:forEach() #295
        +---[0.018547ms] com.esell.spring.boot.starter.mybatis.plugin.pagination.PaginationBean:toPagination() #311
        +---[0.017203ms] com.esell.gw.yxfbp.common.PaginationApiResponse:<init>() #311
        `---[0.961965ms] com.esell.yxf.common.util.LoggerMainBuilderUtils:responseLog() #313

4) 筛选指定耗时的方法

不少时候咱们只想看到某个方法的rt大于某个时间以后的trace结果，如今Arthas能够按照方法执行的耗时来进行过滤了，例如trace *StringUtils isBlank '#cost>100'表示当执行时间超过100ms的时候，才会输出trace的结果。

trace -E com.esell.gw.yxfbp.iot.manage.PublishManager|com.esell.v2.device.controller.DeviceBaseController updateAd|listDevice '#cost > 15607'

输出

$ trace -E com.esell.gw.yxfbp.iot.manage.PublishManager|com.esell.v2.device.controller.DeviceBaseController updateAd|listDevice '#cost > 15607'
Press Q or Ctrl+C to abort.
Affect(class-cnt:2 , method-cnt:2) cost in 1179 ms.
`---ts=2019-07-23 11:47:21;thread_name=http-nio-8080-exec-60;id=e5;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@211d9483
    `---[19575.706387ms] com.esell.gw.yxfbp.iot.manage.PublishManager:updateAd()
        +---[0.00811ms] java.lang.Integer:intValue() #76
        +---[2.816689ms] com.esell.gw.yxfbp.rew.adDisplay.mapper.AdDisplayMapper:selectDeviceIdsByAdId() #78
        +---[0.035768ms] org.apache.commons.collections4.CollectionUtils:isNotEmpty() #79
        +---[29.068075ms] com.esell.v2.device.dao.DeviceBaseDao:listUuidById() #80
        `---[19542.923598ms] java.util.List:forEach() #81

重点提醒

trace能方便的帮助你定位和发现因 RT 高而致使的性能问题缺陷，但其每次只能跟踪一级方法的调用链路。

trace命令只会trace匹配到的函数里的子调用，并不会向下trace多层。由于trace是代价比较贵的，多层trace可能会致使最终要trace的类和函数很是多

6. 对方法执行数据的观测

watch

方法执行数据观测

让你能方便的观察到指定方法的调用状况。能观察到的范围为：返回值、抛出异常、入参

参数说明

watch 的参数比较多，主要是由于它能在 4 个不一样的场景观察对象

参数名称	参数说明
class-pattern	类名表达式匹配
method-pattern	方法名表达式匹配
express	观察表达式
condition-express	条件表达式
[b]	在方法调用以前观察
[e]	在方法异常以后观察
[s]	在方法返回以后观察
[f]	在方法结束以后(正常返回和异常返回)观察
[E]	开启正则表达式匹配，默认为通配符匹配
[x:]	指定输出结果的属性遍历深度，默认为 1

对于观察表达式，单个能够这么写 "params"，多个则是"{params,returnObj,throwExp}"，只要是一个合法的 ognl 表达式，都能被正常支持。更多的表达式变量请参考表达式核心变量中关于该节点的描述。

同时对于Arthas中ognl表达式的更多特殊例子可参考 Arthas的一些特殊用法文档说明

特别说明：

watch 命令定义了4个观察事件点，即 -b 方法调用前，-e 方法异常后，-s 方法返回后，-f 方法结束后
4个观察事件点 -b、-e、-s 默认关闭，-f 默认打开，当指定观察点被打开后，在相应事件点会对观察表达式进行求值并输出
这里要注意方法入参和方法出参的区别，有可能在中间被修改致使先后不一致，除了 -b 事件点 params 表明方法入参外，其他事件都表明方法出参
当使用 -b 时，因为观察事件点是在方法调用前，此时返回值或异常均不存在
-x 表示遍历深度，能够调整来打印具体的参数和结果内容，默认值是1

1) 查看方法的请求参数和返回参数

-x 参数的值可根据实际参数的遍历深度进行设置，若是须要查看resultObj的具体值，能够调整-x的值

watch *DeviceBaseController listDevice "{params,returnObj}" -x 2

输出，能够看到result中有两个结果，第一个是请求参数，第二个是返回参数

$ watch *DeviceBaseController listDevice "{params,returnObj}" -x 2
Press Q or Ctrl+C to abort.
Affect(class-cnt:6 , method-cnt:2) cost in 833 ms.
ts=2019-07-24 11:56:39; [cost=311.854619ms] result=@ArrayList[
    @Object[][
        @SimpleApiRequest[{"sign":"b3d98718d6ceff8c1668c43592019cf2","appid":"Jvddh8LKdLwmZ3cw","version":"1.3","sequence":1563940597279,"timestamp":1563940597279,"payload":"{\"page\":1,\"size\":10,\"uuid\":\"\",\"group-id\":\"\",\"gatherId\":\"\",\"name\":\"\",\"open\":\"\",\"district-code\":\"\",\"status\":\"\",\"phone-number\":\"\"}"}],
        @RequestFacade[org.apache.catalina.connector.RequestFacade@68db1322],
    ],
    @PaginationApiResponse[
        serialVersionUID=@Long[4126749321937797939],
    ],
]

2) 查看方法的参数的指定属性

查看请求的uuid值

watch *DeviceBaseController listDevice "{params[0].payload.uuid,returnObj}" -x 2

输出，可看到uuid为519073369656

$ watch *DeviceBaseController listDevice "{params[0].payload.uuid,returnObj}" -x 2
Press Q or Ctrl+C to abort.
Affect(class-cnt:6 , method-cnt:2) cost in 757 ms.
ts=2019-07-24 12:01:08; [cost=147.622644ms] result=@ArrayList[
    @String[     519073369656],
    @PaginationApiResponse[
        serialVersionUID=@Long[4126749321937797939],
    ],
]

3) 根据条件过滤

当请求参数的uuid为519073369656才输出

watch *DeviceBaseController listDevice "{params[0],returnObj}" "params[0].payload.uuid=='519073369656'" -x 2

输出

$ watch *DeviceBaseController listDevice "{params[0],returnObj}" "params[0].payload.uuid=='519073369656'" -x 2
Press Q or Ctrl+C to abort.
Affect(class-cnt:6 , method-cnt:2) cost in 794 ms.
ts=2019-07-24 12:04:27; [cost=79.459047ms] result=@ArrayList[
    @SimpleApiRequest[
        serialVersionUID=@Long[7777957270454431721],
    ],
    @PaginationApiResponse[
        serialVersionUID=@Long[4126749321937797939],
    ],
]

4) 查看异常的输出

watch *TemplateV2ServiceImpl addTemplate "throwExp" -e  -x 2

输出

$ watch *TemplateV2ServiceImpl addTemplate "throwExp" -e  -x 2
Press Q or Ctrl+C to abort.
Affect(class-cnt:2 , method-cnt:2) cost in 439 ms.
ts=2019-07-24 12:45:12; [cost=64.79821ms] result=@ArrayList[
    com.esell.exception.EsellException: 互动按钮跳转未设置，请退出从新编辑 [DEBUG: 互动按钮跳转未设置，请退出从新编辑]
.............................

5) 筛选指定耗时的方法

大于10ms的耗时才被输出

watch *TemplateV2ServiceImpl addTemplate "params" -x 2 '#cost>10'

输出，耗时103.519568ms

$ watch *TemplateV2ServiceImpl addTemplate "params" -x 2 '#cost>10'
Press Q or Ctrl+C to abort.
Affect(class-cnt:2 , method-cnt:2) cost in 313 ms.
ts=2019-07-24 12:49:49; [cost=103.519568ms] result=@Object[][
    @TemplateV2SearchDto[
        templateId=null,
        name=@String[1111jjjj],
        accountId=@Integer[86],
        crmCode=@String[C1804111843],
        width=@Integer[1920],
        height=@Integer[1080],
        pageList=@String[[{"slotNum":1,"name":"页面1","page":[{"openRtb":"0","componentId":1261,"src":"","h":200,"type":"slot","materialId":"","templateId":8089,"slotName":"广告位1","adSwitchType":"0","w":3":702,"rtbCpm":"0","y":602,"slotId":11379,"zIndex":1}],"id":1001}]],
        groupGuid=null,
        scaleRatio=@String[1],
        tempCover=@ArrayList[isEmpty=false;size=1],
        components=@ArrayList[isEmpty=false;size=1],
    ],
]

6) 对多个类的多个方法的参数进行查看

注意此处不能使用通配符

watch -E com.esell.v2.device.controller.DeviceBaseController|com.esell.v2.template.controller.TemplateV2Controller listDevice|search 'params[0].payload' -x 3

输出

$ watch -E com.esell.v2.device.controller.DeviceBaseController|com.esell.v2.template.controller.TemplateV2Controller listDevice|search 'params[0].payload' -x 3
Press Q or Ctrl+C to abort.
Affect(class-cnt:2 , method-cnt:2) cost in 577 ms.
ts=2019-07-24 15:20:39; [cost=11.840307ms] result=@JSONObject[
    @String[size]:@Integer[8],
    @String[name]:@String[],
    @String[page]:@Integer[1],
]
ts=2019-07-24 15:20:41; [cost=344.565606ms] result=@JSONObject[
    @String[phone-number]:@String[],
    @String[size]:@Integer[10],
    @String[group-id]:@String[],
    @String[gatherId]:@String[],
    @String[name]:@String[],
    @String[page]:@Integer[1],
    @String[district-code]:@String[],
    @String[uuid]:@String[],
    @String[open]:@String[],
    @String[status]:@String[],
]

7. 获取不一样时间方法执行的记录

方法执行数据的时空隧道，记录下指定方法每次调用的入参和返回信息，并能对这些不一样的时间下调用进行观测

watch 虽然很方便和灵活，但须要提早想清楚观察表达式的拼写，这对排查问题而言要求过高，由于不少时候咱们并不清楚问题出自于何方，只能靠蛛丝马迹进行猜想。

这个时候若是能记录下当时方法调用的全部入参和返回值、抛出的异常会对整个问题的思考与判断很是有帮助。

因而乎，TimeTunnel 命令就诞生了。

命令参数解析
-t

tt 命令有不少个主参数，-t 就是其中之一。这个参数的代表但愿记录下类 *Test 的 print 方法的每次执行状况。
-n 3

当你执行一个调用量不高的方法时可能你还能有足够的时间用 CTRL+C 中断 tt 命令记录的过程，但若是遇到调用量很是大的方法，瞬间就能将你的 JVM 内存撑爆。

此时你能够经过 -n 参数指定你须要记录的次数，当达到记录次数时 Arthas 会主动中断tt命令的记录过程，避免人工操做没法中止的状况。
表格字段说明

表格字段	字段解释
INDEX	时间片断记录编号，每个编号表明着一次调用，后续tt还有不少命令都是基于此编号指定记录操做，很是重要。
TIMESTAMP	方法执行的本机时间，记录了这个时间片断所发生的本机时间
COST(ms)	方法执行的耗时
IS-RET	方法是否以正常返回的形式结束
IS-EXP	方法是否以抛异常的形式结束
OBJECT	执行对象的`hashCode()`，注意，曾经有人误认为是对象在JVM中的内存地址，但很遗憾他不是。但他能帮助你简单的标记当前执行方法的类实体
CLASS	执行的类名
METHOD	执行的方法名

条件表达式

不知道你们是否有在使用过程当中遇到如下困惑
Arthas 彷佛很难区分出重载的方法
我只须要观察特定参数，可是 tt 却所有都给我记录了下来

条件表达式也是用 OGNL 来编写，核心的判断对象依然是 Advice 对象。除了 tt 命令以外，watch、trace、stack 命令也都支持条件表达式。
解决方法重载

tt -t *Test print params.length==1

经过制定参数个数的形式解决不一样的方法签名，若是参数个数同样，你还能够这样写

tt -t *Test print 'params[1] instanceof Integer'
解决指定参数

tt -t *Test print params[0].mobile=="13989838402"
构成条件表达式的 Advice 对象

前边看到了不少条件表达式中，都使用了 params[0]，有关这个变量的介绍，请参考表达式核心变量

1) 获取方法的调用记录

tt -t *.DeviceBaseController listDevice

输出

2) 根据条件过滤

条件表达式也是用 OGNL 来编写，核心的判断对象依然是 Advice 对象。除了 tt 命令以外，watch、trace、stack 命令也都支持条件表达式。

tt -t *.DeviceBaseController listDevice 'params[0].payload.uuid==519'

输出

3) 获取以前的调用记录

tt -l

输出

4) 根据条件从调用记录中筛选

你须要一个 -s 参数。一样的，搜索表达式的核心对象依旧是 Advice 对象。

tt -s 'method.name == "listDevice"'

输出

5) 查看方法的具体调用信息

对于具体一个时间片的信息而言，你能够经过 -i 参数后边跟着对应的 INDEX 编号查看到他的详细信息。能够经过-x来查看更深层详细的参数输出

tt -i 1002

输出

6) 对方法从新调用

当你稍稍作了一些调整以后，你可能须要前端系统从新触发一次你的调用，此时得求爷爷告奶奶的须要前端配合联调的同窗再次发起一次调用。而有些场景下，这个调用不是这么好触发的。

tt 命令因为保存了当时调用的全部现场信息，因此咱们能够本身主动对一个 INDEX 编号的时间片自主发起一次调用，从而解放你的沟通成本。此时你须要 -p 参数。经过 --replay-times 指定调用次数，经过 --replay-interval 指定屡次调用间隔(单位ms, 默认1000ms)

tt -i 1002 -p

输出

你会发现结果虽然同样，但调用的路径发生了变化，有原来的程序发起变成了 Arthas 本身的内部线程发起的调用了。

注意

ThreadLocal 信息丢失

不少框架偷偷的将一些环境变量信息塞到了发起调用线程的 ThreadLocal 中，因为调用线程发生了变化，这些 ThreadLocal 线程信息没法经过 Arthas 保存，因此这些信息将会丢失。

一些常见的 CASE 好比：鹰眼的 TraceId 等。
引用的对象

须要强调的是，tt 命令是将当前环境的对象引用保存起来，但仅仅也只能保存一个引用而已。若是方法内部对入参进行了变动，或者返回的对象通过了后续的处理，那么在 tt 查看的时候将没法看到当时最准确的值。这也是为何 watch 命令存在的意义。

欢迎关注公众号，后续文章更新通知，一块儿讨论技术问题。