1. 程式人生 > >Arthas - Java 線上問題定位處理的終極利器

Arthas - Java 線上問題定位處理的終極利器

前言

在使用 Arthas 之前,當遇到 Java 線上問題時,如 CPU 飆升、負載突高、記憶體溢位等問題,你需要查命令,查網路,然後 jps、jstack、jmap、jhat、jstat、hprof 等一通操作。最終焦頭爛額,還不一定能查出問題所在。而現在,大多數的常見問題你都可以使用 Arthas 輕鬆定位,迅速解決,及時止損,準時下班。

1、Arthas 介紹

Arthas 是 Alibaba 在 2018 年 9 月開源的 Java 診斷工具。支援 JDK6+, 採用命令列互動模式,提供 Tab 自動不全,可以方便的定位和診斷線上程式執行問題。截至本篇文章編寫時,已經收穫 Star

17000+。

Arthas 官方文件十分詳細,本文也參考了官方文件內容,同時在開源在的 Github 的專案裡的 Issues 裡不僅有問題反饋,更有大量的使用案例,也可以進行學習參考。

開源地址:https://github.com/alibaba/arthas

官方文件:https://alibaba.github.io/arthas

2、Arthas 使用場景

得益於 Arthas 強大且豐富的功能,讓 Arthas 能做的事情超乎想象。下面僅僅列舉幾項常見的使用情況,更多的使用場景可以在熟悉了 Arthas 之後自行探索。

  1. 是否有一個全域性視角來檢視系統的執行狀況?
  2. 為什麼 CPU 又升高了,到底是哪裡佔用了 CPU ?
  3. 執行的多執行緒有死鎖嗎?有阻塞嗎?
  4. 程式執行耗時很長,是哪裡耗時比較長呢?如何監測呢?
  5. 這個類從哪個 jar 包載入的?為什麼會報各種類相關的 Exception?
  6. 我改的程式碼為什麼沒有執行到?難道是我沒 commit?分支搞錯了?
  7. 遇到問題無法在線上 debug,難道只能通過加日誌再重新發布嗎?
  8. 有什麼辦法可以監控到 JVM 的實時執行狀態?

3、Arthas 怎麼用

前文已經提到,Arthas 是一款命令列互動模式的 Java 診斷工具,由於是 Java 編寫,所以可以直接下載相應 的 jar 包執行。

3.1 安裝

可以在官方 Github 上進行下載,如果速度較慢,可以嘗試國內的碼雲 Gitee 下載。

# github下載
wget https://alibaba.github.io/arthas/arthas-boot.jar
# 或者 Gitee 下載
wget https://arthas.gitee.io/arthas-boot.jar
# 列印幫助資訊
java -jar arthas-boot.jar -h

3.2 執行

Arthas 只是一個 java 程式,所以可以直接用 java -jar 執行。執行時或者執行之後要選擇要監測的 Java 程序。

# 執行方式1,先執行,在選擇 Java 程序 PID
java -jar arthas-boot.jar
# 選擇程序(輸入[]內編號(不是PID)回車)
[INFO] arthas-boot version: 3.1.4
[INFO] Found existing java process, please choose one and hit RETURN.
* [1]: 11616 com.Arthas
  [2]: 8676
  [3]: 16200 org.jetbrains.jps.cmdline.Launcher
  [4]: 21032 org.jetbrains.idea.maven.server.RemoteMavenServer

# 執行方式2,執行時選擇 Java 程序 PID
java -jar arthas-boot.jar [PID]

檢視 PID 的方式可以通過 ps 命令,也可以通過 JDK 提供的 jps命令。

# 檢視執行的 java 程序資訊
$ jps -mlvV 
# 篩選 java 程序資訊
$ jps -mlvV | grep [xxx]

jps 篩選想要的程序方式。

在出現 Arthas Logo 之後就可以使用命令進行問題診斷了。下面會詳細介紹。

更多的啟動方式可以參考 help 幫助命令。

# 其他用法
EXAMPLES:
  java -jar arthas-boot.jar <pid>
  java -jar arthas-boot.jar --target-ip 0.0.0.0
  java -jar arthas-boot.jar --telnet-port 9999 --http-port -1
  java -jar arthas-boot.jar --tunnel-server 'ws://192.168.10.11:7777/ws'
  java -jar arthas-boot.jar --tunnel-server 'ws://192.168.10.11:7777/ws'
--agent-id bvDOe8XbTM2pQWjF4cfw
  java -jar arthas-boot.jar --stat-url 'http://192.168.10.11:8080/api/stat'
  java -jar arthas-boot.jar -c 'sysprop; thread' <pid>
  java -jar arthas-boot.jar -f batch.as <pid>
  java -jar arthas-boot.jar --use-version 3.1.4
  java -jar arthas-boot.jar --versions
  java -jar arthas-boot.jar --session-timeout 3600
  java -jar arthas-boot.jar --attach-only
  java -jar arthas-boot.jar --repo-mirror aliyun --use-http

3.3 web console

Arthas 目前支援 Web Console,在成功啟動連線程序之後就已經自動啟動,可以直接訪問 http://127.0.0.1:8563/ 訪問,頁面上的操作模式和控制檯完全一樣。

3.4 常用命令

下面列舉一些 Arthas 的常用命令,看到這裡你可能還不知道怎麼使用,別急,後面會一一介紹。

命令 介紹
dashboard 當前系統的實時資料面板
thread 檢視當前 JVM 的執行緒堆疊資訊
watch 方法執行資料觀測
trace 方法內部呼叫路徑,並輸出方法路徑上的每個節點上耗時
stack 輸出當前方法被呼叫的呼叫路徑
tt 方法執行資料的時空隧道,記錄下指定方法每次呼叫的入參和返回資訊,並能對這些不同的時間下呼叫進行觀測
monitor 方法執行監控
jvm 檢視當前 JVM 資訊
vmoption 檢視,更新 JVM 診斷相關的引數
sc 檢視 JVM 已載入的類資訊
sm 檢視已載入類的方法資訊
jad 反編譯指定已載入類的原始碼
classloader 檢視 classloader 的繼承樹,urls,類載入資訊
heapdump 類似 jmap 命令的 heap dump 功能

3.5 退出

使用 shutdown 退出時 Arthas 同時自動重置所有增強過的類 。

4、Arthas 常用操作

上面已經瞭解了什麼是 Arthas,以及 Arthas 的啟動方式,下面會依據一些情況,詳細說一說 Arthas 的使用方式。在使用命令的過程中如果有問題,每個命令都可以是 -h 檢視幫助資訊。

首先編寫一個有各種情況的測試類執行起來,再使用 Arthas 進行問題定位,

import java.util.HashSet;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import lombok.extern.slf4j.Slf4j;

/**
 * <p>
 * Arthas Demo
 * 公眾號:未讀程式碼
 *
 * @Author niujinpeng
 */
@Slf4j
public class Arthas {

    private static HashSet hashSet = new HashSet();
    /** 執行緒池,大小1*/
    private static ExecutorService executorService = Executors.newFixedThreadPool(1);

    public static void main(String[] args) {
        // 模擬 CPU 過高,這裡註釋掉了,測試時可以開啟
        // cpu();
        // 模擬執行緒阻塞
        thread();
        // 模擬執行緒死鎖
        deadThread();
        // 不斷的向 hashSet 集合增加資料
        addHashSetThread();
    }

    /**
     * 不斷的向 hashSet 集合新增資料
     */
    public static void addHashSetThread() {
        // 初始化常量
        new Thread(() -> {
            int count = 0;
            while (true) {
                try {
                    hashSet.add("count" + count);
                    Thread.sleep(10000);
                    count++;
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }
        }).start();
    }

    public static void cpu() {
        cpuHigh();
        cpuNormal();
    }

    /**
     * 極度消耗CPU的執行緒
     */
    private static void cpuHigh() {
        Thread thread = new Thread(() -> {
            while (true) {
                log.info("cpu start 100");
            }
        });
        // 新增到執行緒
        executorService.submit(thread);
    }

    /**
     * 普通消耗CPU的執行緒
     */
    private static void cpuNormal() {
        for (int i = 0; i < 10; i++) {
            new Thread(() -> {
                while (true) {
                    log.info("cpu start");
                    try {
                        Thread.sleep(3000);
                    } catch (InterruptedException e) {
                        e.printStackTrace();
                    }
                }
            }).start();
        }
    }

    /**
     * 模擬執行緒阻塞,向已經滿了的執行緒池提交執行緒
     */
    private static void thread() {
        Thread thread = new Thread(() -> {
            while (true) {
                log.debug("thread start");
                try {
                    Thread.sleep(3000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }
        });
        // 新增到執行緒
        executorService.submit(thread);
    }

    /**
     * 死鎖
     */
    private static void deadThread() {
        /** 建立資源 */
        Object resourceA = new Object();
        Object resourceB = new Object();
        // 建立執行緒
        Thread threadA = new Thread(() -> {
            synchronized (resourceA) {
                log.info(Thread.currentThread() + " get ResourceA");
                try {
                    Thread.sleep(1000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
                log.info(Thread.currentThread() + "waiting get resourceB");
                synchronized (resourceB) {
                    log.info(Thread.currentThread() + " get resourceB");
                }
            }
        });

        Thread threadB = new Thread(() -> {
            synchronized (resourceB) {
                log.info(Thread.currentThread() + " get ResourceB");
                try {
                    Thread.sleep(1000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
                log.info(Thread.currentThread() + "waiting get resourceA");
                synchronized (resourceA) {
                    log.info(Thread.currentThread() + " get resourceA");
                }
            }
        });
        threadA.start();
        threadB.start();
    }
}

4.1 全域性監控

使用 dashboard 命令可以概覽程式的 執行緒、記憶體、GC、執行環境資訊。

4.2 CPU 為什麼起飛了

上面的程式碼例子有一個 CPU 空轉的死迴圈,非常的消耗 CPU效能,那麼怎麼找出來呢?

使用 thread檢視所有執行緒資訊,同時會列出每個執行緒的 CPU 使用率,可以看到圖裡 ID 為12 的執行緒 CPU 使用100%。

使用命令 thread 12 檢視 CPU 消耗較高的 12 號執行緒資訊,可以看到 CPU 使用較高的方法和行數(這裡的行數可能和上面程式碼裡的行數有區別,因為上面的程式碼在我寫文章時候重新排過版了)。

上面是先通過觀察總體的執行緒資訊,然後檢視具體的執行緒執行情況。如果只是為了尋找 CPU 使用較高的執行緒,可以直接使用命令 thread -n [顯示的執行緒個數] ,就可以排列出 CPU 使用率 Top N 的執行緒。

定位到的 CPU 使用最高的方法。

4.3 執行緒池執行緒狀態

定位執行緒問題之前,先回顧一下執行緒的幾種常見狀態:

  • RUNNABLE 執行中
  • TIMED_WAITIN 呼叫了以下方法的執行緒會進入TIMED_WAITING:
    1. Thread#sleep()
    2. Object#wait() 並加了超時引數
    3. Thread#join() 並加了超時引數
    4. LockSupport#parkNanos()
    5. LockSupport#parkUntil()
  • WAITING 當執行緒呼叫以下方法時會進入WAITING狀態:
    1. Object#wait() 而且不加超時引數
    2. Thread#join() 而且不加超時引數
    3. LockSupport#park()
  • BLOCKED 阻塞,等待鎖

上面的模擬程式碼裡,定義了執行緒池大小為1 的執行緒池,然後在 cpuHigh 方法裡提交了一個執行緒,在 thread方法再次提交了一個執行緒,後面的這個執行緒因為執行緒池已滿,會阻塞下來。

使用 thread | grep pool 命令檢視執行緒池裡執行緒資訊。

可以看到執行緒池有 WAITING 的執行緒。

4.4 執行緒死鎖

上面的模擬程式碼裡 deadThread方法實現了一個死鎖,使用 thread -b 命令檢視直接定位到死鎖資訊。

/**
 * 死鎖
 */
private static void deadThread() {
    /** 建立資源 */
    Object resourceA = new Object();
    Object resourceB = new Object();
    // 建立執行緒
    Thread threadA = new Thread(() -> {
        synchronized (resourceA) {
            log.info(Thread.currentThread() + " get ResourceA");
            try {
                Thread.sleep(1000);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
            log.info(Thread.currentThread() + "waiting get resourceB");
            synchronized (resourceB) {
                log.info(Thread.currentThread() + " get resourceB");
            }
        }
    });

    Thread threadB = new Thread(() -> {
        synchronized (resourceB) {
            log.info(Thread.currentThread() + " get ResourceB");
            try {
                Thread.sleep(1000);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
            log.info(Thread.currentThread() + "waiting get resourceA");
            synchronized (resourceA) {
                log.info(Thread.currentThread() + " get resourceA");
            }
        }
    });
    threadA.start();
    threadB.start();
}

檢查到的死鎖資訊。

4.5 反編譯

上面的程式碼放到了包 com下,假設這是一個執行緒環境,當懷疑當前執行的程式碼不是自己想要的程式碼時,可以直接反編譯出程式碼,也可以選擇性的檢視類的欄位或方法資訊。

如果懷疑不是自己的程式碼,可以使用 jad 命令直接反編譯 class。

jad 命令還提供了一些其他引數:

# 反編譯只顯示原始碼
jad --source-only com.Arthas
# 反編譯某個類的某個方法
jad --source-only com.Arthas mysql

4.6 檢視欄位資訊

使用 sc -d -f 命令檢視類的欄位資訊。

[arthas@20252]$ sc -d -f com.Arthas
sc -d -f com.Arthas
 class-info        com.Arthas
 code-source       /C:/Users/Niu/Desktop/arthas/target/classes/
 name              com.Arthas
 isInterface       false
 isAnnotation      false
 isEnum            false
 isAnonymousClass  false
 isArray           false
 isLocalClass      false
 isMemberClass     false
 isPrimitive       false
 isSynthetic       false
 simple-name       Arthas
 modifier          public
 annotation
 interfaces
 super-class       +-java.lang.Object
 class-loader      +-sun.misc.Launcher$AppClassLoader@18b4aac2
                     +-sun.misc.Launcher$ExtClassLoader@2ef1e4fa
 classLoaderHash   18b4aac2
 fields            modifierfinal,private,static
                   type    org.slf4j.Logger
                   name    log
                   value   Logger[com.Arthas]

                   modifierprivate,static
                   type    java.util.HashSet
                   name    hashSet
                   value   [count1, count2]

                   modifierprivate,static
                   type    java.util.concurrent.ExecutorService
                   name    executorService
                   value   java.util.concurrent.ThreadPoolExecutor@71c03156[Ru
                           nning, pool size = 1, active threads = 1, queued ta
                           sks = 0, completed tasks = 0]


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

4.7 檢視方法資訊

使用 sm 命令檢視類的方法資訊。

[arthas@22180]$ sm com.Arthas
com.Arthas <init>()V
com.Arthas start()V
com.Arthas thread()V
com.Arthas deadThread()V
com.Arthas lambda$cpuHigh$1()V
com.Arthas cpuHigh()V
com.Arthas lambda$thread$3()V
com.Arthas addHashSetThread()V
com.Arthas cpuNormal()V
com.Arthas cpu()V
com.Arthas lambda$addHashSetThread$0()V
com.Arthas lambda$deadThread$4(Ljava/lang/Object;Ljava/lang/Object;)V
com.Arthas lambda$deadThread$5(Ljava/lang/Object;Ljava/lang/Object;)V
com.Arthas lambda$cpuNormal$2()V
Affect(row-cnt:16) cost in 6 ms.

4.8 對變數的值很是好奇

使用 ognl 命令,ognl 表示式可以輕鬆操作想要的資訊。

程式碼還是上面的示例程式碼,我們檢視變數 hashSet 中的資料:

檢視靜態變數 hashSet 資訊。

[arthas@19856]$ ognl '@com.Arthas@hashSet'
@HashSet[
    @String[count1],
    @String[count2],
    @String[count29],
    @String[count28],
    @String[count0],
    @String[count27],
    @String[count5],
    @String[count26],
    @String[count6],
    @String[count25],
    @String[count3],
    @String[count24],

檢視靜態變數 hashSet 大小。

[arthas@19856]$ ognl '@[email protected]()'
    @Integer[57]

甚至可以進行操作。

[arthas@19856]$ ognl  '@[email protected]("test")'
    @Boolean[true]
[arthas@19856]$
# 檢視新增的字元
[arthas@19856]$ ognl  '@com.Arthas@hashSet' | grep test
    @String[test],
[arthas@19856]$

ognl 可以做很多事情,可以參考 ognl 表示式特殊用法( https://github.com/alibaba/arthas/issues/71 )。

4.9 程式有沒有問題

4.9.1 執行較慢、耗時較長

使用 trace 命令可以跟蹤統計方法耗時

這次換一個模擬程式碼。一個最基礎的 Springboot 專案(當然,不想 Springboot 的話,你也可以直接在 UserController 裡 main 方法啟動)控制層 getUser 方法呼叫了 userService.get(uid);,這個方法中分別進行checkserviceredismysql操作。

@RestController
@Slf4j
public class UserController {

    @Autowired
    private UserServiceImpl userService;

    @GetMapping(value = "/user")
    public HashMap<String, Object> getUser(Integer uid) throws Exception {
        // 模擬使用者查詢
        userService.get(uid);
        HashMap<String, Object> hashMap = new HashMap<>();
        hashMap.put("uid", uid);
        hashMap.put("name", "name" + uid);
        return hashMap;
    }
}

模擬程式碼 Service:

@Service
@Slf4j
public class UserServiceImpl {

    public void get(Integer uid) throws Exception {
        check(uid);
        service(uid);
        redis(uid);
        mysql(uid);
    }

    public void service(Integer uid) throws Exception {
        int count = 0;
        for (int i = 0; i < 10; i++) {
            count += i;
        }
        log.info("service  end {}", count);
    }

    public void redis(Integer uid) throws Exception {
        int count = 0;
        for (int i = 0; i < 10000; i++) {
            count += i;
        }
        log.info("redis  end {}", count);
    }

    public void mysql(Integer uid) throws Exception {
        long count = 0;
        for (int i = 0; i < 10000000; i++) {
            count += i;
        }
        log.info("mysql end {}", count);
    }

     public boolean check(Integer uid) throws Exception {
         if (uid == null || uid < 0) {
             log.error("uid不正確,uid:{}", uid);
             throw new Exception("uid不正確");
         }
         return true;
     }
}

執行 Springboot 之後,使用 trace== 命令開始檢測耗時情況。

[arthas@6592]$ trace com.UserController getUser

訪問介面 /getUser ,可以看到耗時資訊,看到 com.UserServiceImpl:get()方法耗時較高。

繼續跟蹤耗時高的方法,然後再次訪問。

[arthas@6592]$ trace com.UserServiceImpl get

很清楚的看到是 com.UserServiceImplmysql方法耗時是最高的。

Affect(class-cnt:1 , method-cnt:1) cost in 31 ms.
`---ts=2019-10-16 14:40:10;thread_name=http-nio-8080-exec-8;id=1f;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@23a918c7
    `---[6.792201ms] com.UserServiceImpl:get()
        +---[0.008ms] com.UserServiceImpl:check() #17
        +---[0.076ms] com.UserServiceImpl:service() #18
        +---[0.1089ms] com.UserServiceImpl:redis() #19
        `---[6.528899ms] com.UserServiceImpl:mysql() #20

4.9.2 統計方法耗時

使用 monitor 命令監控統計方法的執行情況。

每5秒統計一次 com.UserServiceImpl 類的 get 方法執行情況。

monitor -c 5 com.UserServiceImpl get

4.10 想觀察方法資訊

下面的示例用到了文章的前兩個模擬程式碼。

4.10.1 觀察方法的入參出參資訊

使用 watch 命令輕鬆檢視輸入輸出引數以及異常等資訊。

 USAGE:
   watch [-b] [-e] [-x <value>] [-f] [-h] [-n <value>] [-E] [-M <value>] [-s] class-pattern method-pattern express [condition-express]

 SUMMARY:
   Display the input/output parameter, return object, and thrown exception of specified method invocation
   The express may be one of the following expression (evaluated dynamically):
           target : the object
            clazz : the object's class
           method : the constructor or method
           params : the parameters array of method
     params[0..n] : the element of parameters array
        returnObj : the returned object of method
         throwExp : the throw exception of method
         isReturn : the method ended by return
          isThrow : the method ended by throwing exception
            #cost : the execution time in ms of method invocation
 Examples:
   watch -b org.apache.commons.lang.StringUtils isBlank params
   watch -f org.apache.commons.lang.StringUtils isBlank returnObj
   watch org.apache.commons.lang.StringUtils isBlank '{params, target, returnObj}' -x 2
   watch -bf *StringUtils isBlank params
   watch *StringUtils isBlank params[0]
   watch *StringUtils isBlank params[0] params[0].length==1
   watch *StringUtils isBlank params '#cost>100'
   watch -E -b org\.apache\.commons\.lang\.StringUtils isBlank params[0]

 WIKI:
   https://alibaba.github.io/arthas/watch

常用操作:

# 檢視入參和出參
$ watch com.Arthas addHashSet '{params[0],returnObj}'
# 檢視入參和出參大小
$ watch com.Arthas addHashSet '{params[0],returnObj.size}'
# 檢視入參和出參中是否包含 'count10'
$ watch com.Arthas addHashSet '{params[0],returnObj.contains("count10")}'
# 檢視入參和出參,出參 toString
$ watch com.Arthas addHashSet '{params[0],returnObj.toString()}'

檢視入參出參。

檢視返回的異常資訊。

4.10.2 觀察方法的呼叫路徑

使用 stack命令檢視方法的呼叫資訊。

# 觀察 類com.UserServiceImpl的 mysql 方法呼叫路徑
stack com.UserServiceImpl mysql

4.10.3 方法呼叫時空隧道

使用 tt 命令記錄方法執行的詳細情況。

tt 命令方法執行資料的時空隧道,記錄下指定方法每次呼叫的入參和返回資訊,並能對這些不同的時間下呼叫進行觀測 。

常用操作:

開始記錄方法呼叫資訊:tt -t com.UserServiceImpl check

可以看到記錄中 INDEX=1001 的記錄的 IS-EXP = true ,說明這次調用出現異常。

檢視記錄的方法呼叫資訊: tt -l

檢視呼叫記錄的詳細資訊(-i 指定 INDEX): tt -i 1001

可以看到 INDEX=1001 的記錄的異常資訊。

重新發起呼叫,使用指定記錄,使用 -p 重新呼叫。

tt -i 1001 -p

文中程式碼已經上傳到 Github。

https://github.com/niumoo/lab-notes/tree/master/src/main/java/net/codingme/arthas

<完>

本文作者:未讀程式碼
我的微信:wn8398
個人主頁:https://www.codingme.net
本篇文章是博主原創文章,歡迎轉載,轉載時在明顯位置註明原文連結即可。
關注公眾號回覆資源可以獲取Java 核心知識整理&面試資料。