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 命令存在的意義。

歡迎關注公衆號，後續文章更新通知，一塊兒討論技術問題。

相關標籤/搜索

每日一句

每一个你不满意的现在，都有一个你没有努力的曾经。