手把手教你定位常見Java效能問題

學致前端攻略發表於2020-12-19

概述

效能優化一向是後端服務優化的重點，但是線上效能故障問題不是經常出現，或者受限於業務產品，根本就沒辦法出現效能問題，包括筆者自己遇到的效能問題也不多，所以為了提前儲備知識，當出現問題的時候不會手忙腳亂，我們本篇文章來模擬下常見的幾個Java效能故障，來學習怎麼去分析和定位。

預備知識

既然是定位問題，肯定是需要藉助工具，我們先了解下需要哪些工具可以幫忙定位問題。

top命令

top命令使我們最常用的Linux命令之一，它可以實時的顯示當前正在執行的程式的CPU使用率，記憶體使用率等系統資訊。top -Hp pid 可以檢視執行緒的系統資源使用情況。

vmstat命令

vmstat是一個指定週期和採集次數的虛擬記憶體檢測工具，可以統計記憶體，CPU，swap的使用情況，它還有一個重要的常用功能，用來觀察程式的上下文切換。欄位說明如下:

r: 執行佇列中程式數量（當數量大於CPU核數表示有阻塞的執行緒）
b: 等待IO的程式數量
swpd: 使用虛擬記憶體大小
free: 空閒實體記憶體大小
buff: 用作緩衝的記憶體大小(記憶體和硬碟的緩衝區)
cache: 用作快取的記憶體大小（CPU和記憶體之間的緩衝區）
si: 每秒從交換區寫到記憶體的大小，由磁碟調入記憶體
so: 每秒寫入交換區的記憶體大小，由記憶體調入磁碟
bi: 每秒讀取的塊數
bo: 每秒寫入的塊數
in: 每秒中斷數，包括時鐘中斷。
cs: 每秒上下文切換數。
us: 使用者程式執行時間百分比(user time)
sy: 核心系統程式執行時間百分比(system time)
wa: IO等待時間百分比
id: 空閒時間百分比

pidstat命令

pidstat 是 Sysstat 中的一個元件，也是一款功能強大的效能監測工具，top 和 vmstat 兩個命令都是監測程式的記憶體、CPU 以及 I/O 使用情況，而 pidstat 命令可以檢測到執行緒級別的。pidstat命令執行緒切換欄位說明如下：

UID ：被監控任務的真實使用者ID。
TGID ：執行緒組ID。
TID：執行緒ID。
cswch/s：主動切換上下文次數，這裡是因為資源阻塞而切換執行緒，比如鎖等待等情況。
nvcswch/s：被動切換上下文次數，這裡指CPU排程切換了執行緒。

jstack命令

jstack是JDK工具命令，它是一種執行緒堆疊分析工具，最常用的功能就是使用 jstack pid 命令檢視執行緒的堆疊資訊，也經常用來排除死鎖情況。

jstat 命令

它可以檢測Java程式執行的實時情況，包括堆記憶體資訊和垃圾回收資訊，我們常常用來檢視程式垃圾回收情況。常用的命令是jstat -gc pid。資訊欄位說明如下：

S0C：年輕代中 To Survivor 的容量（單位 KB）；
S1C：年輕代中 From Survivor 的容量（單位 KB）；
S0U：年輕代中 To Survivor 目前已使用空間（單位 KB）；
S1U：年輕代中 From Survivor 目前已使用空間（單位 KB）；
EC：年輕代中 Eden 的容量（單位 KB）；
EU：年輕代中 Eden 目前已使用空間（單位 KB）；
OC：老年代的容量（單位 KB）；
OU：老年代目前已使用空間（單位 KB）；
MC：元空間的容量（單位 KB）；
MU：元空間目前已使用空間（單位 KB）；
YGC：從應用程式啟動到取樣時年輕代中 gc 次數；
YGCT：從應用程式啟動到取樣時年輕代中 gc 所用時間 (s)；
FGC：從應用程式啟動到取樣時老年代（Full Gc）gc 次數；
FGCT：從應用程式啟動到取樣時老年代代（Full Gc）gc 所用時間 (s)；
GCT：從應用程式啟動到取樣時 gc 用的總時間 (s)。

jmap命令

jmap也是JDK工具命令，他可以檢視堆記憶體的初始化資訊以及堆記憶體的使用情況，還可以生成dump檔案來進行詳細分析。檢視堆記憶體情況命令jmap -heap pid。

mat記憶體工具

MAT(Memory Analyzer Tool)工具是eclipse的一個外掛(MAT也可以單獨使用)，它分析大記憶體的dump檔案時，可以非常直觀的看到各個物件在堆空間中所佔用的記憶體大小、類例項數量、物件引用關係、利用OQL物件查詢，以及可以很方便的找出物件GC Roots的相關資訊。

idea中也有這麼一個外掛，就是JProfiler。

模擬環境準備

基礎環境jdk1.8，採用SpringBoot框架來寫幾個介面來觸發模擬場景，首先是模擬CPU佔滿情況

CPU佔滿

模擬CPU佔滿還是比較簡單，直接寫一個死迴圈計算消耗CPU即可。

     /**
     * 模擬CPU佔滿
     */
    @GetMapping("/cpu/loop")
    public void testCPULoop() throws InterruptedException {
        System.out.println("請求cpu死迴圈");
        Thread.currentThread().setName("loop-thread-cpu");
        int num = 0;
        while (true) {
            num++;
            if (num == Integer.MAX_VALUE) {
                System.out.println("reset");
            }
            num = 0;
        }

    }

請求介面地址測試curl localhost:8080/cpu/loop,發現CPU立馬飆升到100%

通過執行top -Hp 32805 檢視Java執行緒情況

執行 printf '%x' 32826 獲取16進位制的執行緒id，用於dump資訊查詢，結果為 803a。最後我們執行jstack 32805 |grep -A 20 803a 來檢視下詳細的dump資訊。

這裡dump資訊直接定位出了問題方法以及程式碼行，這就定位出了CPU佔滿的問題。

記憶體洩露

模擬記憶體洩漏借助了ThreadLocal物件來完成，ThreadLocal是一個執行緒私有變數，可以繫結到執行緒上，在整個執行緒的生命週期都會存在，但是由於ThreadLocal的特殊性，ThreadLocal是基於ThreadLocalMap實現的，ThreadLocalMap的Entry繼承WeakReference，而Entry的Key是WeakReference的封裝，換句話說Key就是弱引用，弱引用在下次GC之後就會被回收，如果ThreadLocal在set之後不進行後續的操作，因為GC會把Key清除掉，但是Value由於執行緒還在存活，所以Value一直不會被回收，最後就會發生記憶體洩漏。

/**
     * 模擬記憶體洩漏
     */
    @GetMapping(value = "/memory/leak")
    public String leak() {
        System.out.println("模擬記憶體洩漏");
        ThreadLocal<Byte[]> localVariable = new ThreadLocal<Byte[]>();
        localVariable.set(new Byte[4096 * 1024]);// 為執行緒新增變數
        return "ok";
    }

我們給啟動加上堆記憶體大小限制，同時設定記憶體溢位的時候輸出堆疊快照並輸出日誌。

java -jar -Xms500m -Xmx500m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/heapdump.hprof -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:/tmp/heaplog.log analysis-demo-0.0.1-SNAPSHOT.jar

啟動成功後我們迴圈執行100次,for i in {1..500}; do curl localhost:8080/memory/leak;done,還沒執行完畢，系統已經返回500錯誤了。檢視系統日誌出現瞭如下異常：

java.lang.OutOfMemoryError: Java heap space

我們用jstat -gc pid 命令來看看程式的GC情況。

很明顯，記憶體溢位了，堆記憶體經過45次 Full Gc 之後都沒釋放出可用記憶體，這說明當前堆記憶體中的物件都是存活的，有GC Roots引用，無法回收。那是什麼原因導致記憶體溢位呢？是不是我只要加大記憶體就行了呢？如果是普通的記憶體溢位也許擴大記憶體就行了，但是如果是記憶體洩漏的話，擴大的記憶體不一會就會被佔滿，所以我們還需要確定是不是記憶體洩漏。我們之前儲存了堆 Dump 檔案，這個時候藉助我們的MAT工具來分析下。匯入工具選擇Leak Suspects Report，工具直接就會給你列出問題報告。

這裡已經列出了可疑的4個記憶體洩漏問題，我們點選其中一個檢視詳情。

這裡已經指出了記憶體被執行緒佔用了接近50M的記憶體，佔用的物件就是ThreadLocal。如果想詳細的通過手動去分析的話，可以點選Histogram,檢視最大的物件佔用是誰，然後再分析它的引用關係，即可確定是誰導致的記憶體溢位。

上圖發現佔用記憶體最大的物件是一個Byte陣列，我們看看它到底被那個GC Root引用導致沒有被回收。按照上圖紅框操作指引，結果如下圖：

我們發現Byte陣列是被執行緒物件引用的，圖中也標明，Byte陣列對像的GC Root是執行緒，所以它是不會被回收的，展開詳細資訊檢視，我們發現最終的記憶體佔用物件是被ThreadLocal物件佔據了。這也和MAT工具自動幫我們分析的結果一致。

死鎖

死鎖會導致耗盡執行緒資源，佔用記憶體，表現就是記憶體佔用升高，CPU不一定會飆升(看場景決定)，如果是直接new執行緒，會導致JVM記憶體被耗盡，報無法建立執行緒的錯誤，這也是體現了使用執行緒池的好處。

 ExecutorService service = new ThreadPoolExecutor(4, 10,
            0, TimeUnit.SECONDS, new LinkedBlockingQueue<Runnable>(1024),
            Executors.defaultThreadFactory(),
            new ThreadPoolExecutor.AbortPolicy());
   /**
     * 模擬死鎖
     */
    @GetMapping("/cpu/test")
    public String testCPU() throws InterruptedException {
        System.out.println("請求cpu");
        Object lock1 = new Object();
        Object lock2 = new Object();
        service.submit(new DeadLockThread(lock1, lock2), "deadLookThread-" + new Random().nextInt());
        service.submit(new DeadLockThread(lock2, lock1), "deadLookThread-" + new Random().nextInt());
        return "ok";
    }

public class DeadLockThread implements Runnable {
    private Object lock1;
    private Object lock2;

    public DeadLockThread1(Object lock1, Object lock2) {
        this.lock1 = lock1;
        this.lock2 = lock2;
    }

    @Override
    public void run() {
        synchronized (lock2) {
            System.out.println(Thread.currentThread().getName()+"get lock2 and wait lock1");
            try {
                TimeUnit.MILLISECONDS.sleep(2000);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
            synchronized (lock1) {
                System.out.println(Thread.currentThread().getName()+"get lock1 and lock2 ");
            }
        }
    }
}

我們迴圈請求介面2000次，發現不一會系統就出現了日誌錯誤，執行緒池和佇列都滿了,由於我選擇的當佇列滿了就拒絕的策略，所以系統直接丟擲異常。

java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@2760298 rejected from java.util.concurrent.ThreadPoolExecutor@7ea7cd51[Running, pool size = 10, active threads = 10, queued tasks = 1024, completed tasks = 846]

通過ps -ef|grep java命令找出 Java 程式 pid，執行jstack pid 即可出現java執行緒堆疊資訊，這裡發現了5個死鎖，我們只列出其中一個，很明顯執行緒pool-1-thread-2鎖住了0x00000000f8387d88等待0x00000000f8387d98鎖，執行緒pool-1-thread-1鎖住了0x00000000f8387d98等待鎖0x00000000f8387d88,這就產生了死鎖。

Java stack information for the threads listed above:
===================================================
"pool-1-thread-2":
        at top.luozhou.analysisdemo.controller.DeadLockThread2.run(DeadLockThread.java:30)
        - waiting to lock <0x00000000f8387d98> (a java.lang.Object)
        - locked <0x00000000f8387d88> (a java.lang.Object)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
"pool-1-thread-1":
        at top.luozhou.analysisdemo.controller.DeadLockThread1.run(DeadLockThread.java:30)
        - waiting to lock <0x00000000f8387d88> (a java.lang.Object)
        - locked <0x00000000f8387d98> (a java.lang.Object)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

 Found 5 deadlocks.

執行緒頻繁切換

上下文切換會導致將大量CPU時間浪費在暫存器、核心棧以及虛擬記憶體的儲存和恢復上，導致系統整體效能下降。當你發現系統的效能出現明顯的下降時候，需要考慮是否發生了大量的執行緒上下文切換。

 @GetMapping(value = "/thread/swap")
    public String theadSwap(int num) {
        System.out.println("模擬執行緒切換");
        for (int i = 0; i < num; i++) {
            new Thread(new ThreadSwap1(new AtomicInteger(0)),"thread-swap"+i).start();
        }
        return "ok";
    }
public class ThreadSwap1 implements Runnable {
    private AtomicInteger integer;

    public ThreadSwap1(AtomicInteger integer) {
        this.integer = integer;
    }

    @Override
    public void run() {
        while (true) {
            integer.addAndGet(1);
            Thread.yield(); //讓出CPU資源
        }
    }
}

這裡我建立多個執行緒去執行基礎的原子+1操作，然後讓出 CPU 資源，理論上 CPU 就會去排程別的執行緒，我們請求介面建立100個執行緒看看效果如何，curl localhost:8080/thread/swap?num=100。介面請求成功後，我們執行`vmstat 1 10，表示每1秒列印一次，列印10次，執行緒切換採集結果如下：

procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
101  0 128000 878384    908 468684    0    0     0     0 4071 8110498 14 86  0  0  0
100  0 128000 878384    908 468684    0    0     0     0 4065 8312463 15 85  0  0  0
100  0 128000 878384    908 468684    0    0     0     0 4107 8207718 14 87  0  0  0
100  0 128000 878384    908 468684    0    0     0     0 4083 8410174 14 86  0  0  0
100  0 128000 878384    908 468684    0    0     0     0 4083 8264377 14 86  0  0  0
100  0 128000 878384    908 468688    0    0     0   108 4182 8346826 14 86  0  0  0

這裡我們關注4個指標，r,cs,us,sy。

r=100,說明等待的程式數量是100，執行緒有阻塞。

cs=800多萬，說明每秒上下文切換了800多萬次，這個數字相當大了。

us=14，說明使用者態佔用了14%的CPU時間片去處理邏輯。

sy=86，說明核心態佔用了86%的CPU，這裡明顯就是做上下文切換工作了。

我們通過top命令以及top -Hp pid檢視程式和執行緒CPU情況，發現Java執行緒CPU佔滿了，但是執行緒CPU使用情況很平均，沒有某一個執行緒把CPU吃滿的情況。

PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                            
 87093 root      20   0 4194788 299056  13252 S 399.7 16.1  65:34.67 java

 PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND                                                                             
 87189 root      20   0 4194788 299056  13252 R  4.7 16.1   0:41.11 java                                                                                
 87129 root      20   0 4194788 299056  13252 R  4.3 16.1   0:41.14 java                                                                                
 87130 root      20   0 4194788 299056  13252 R  4.3 16.1   0:40.51 java                                                                                
 87133 root      20   0 4194788 299056  13252 R  4.3 16.1   0:40.59 java                                                                                
 87134 root      20   0 4194788 299056  13252 R  4.3 16.1   0:40.95 java

結合上面使用者態CPU只使用了14%，核心態CPU佔用了86%，可以基本判斷是Java程式執行緒上下文切換導致效能問題。

我們使用pidstat命令來看看Java程式內部的執行緒切換資料，執行pidstat -p 87093 -w 1 10 ,採集資料如下：

11:04:30 PM   UID       TGID       TID   cswch/s nvcswch/s  Command
11:04:30 PM     0         -     87128      0.00     16.07  |__java
11:04:30 PM     0         -     87129      0.00     15.60  |__java
11:04:30 PM     0         -     87130      0.00     15.54  |__java
11:04:30 PM     0         -     87131      0.00     15.60  |__java
11:04:30 PM     0         -     87132      0.00     15.43  |__java
11:04:30 PM     0         -     87133      0.00     16.02  |__java
11:04:30 PM     0         -     87134      0.00     15.66  |__java
11:04:30 PM     0         -     87135      0.00     15.23  |__java
11:04:30 PM     0         -     87136      0.00     15.33  |__java
11:04:30 PM     0         -     87137      0.00     16.04  |__java

根據上面採集的資訊，我們知道Java的執行緒每秒切換15次左右，正常情況下，應該是個位數或者小數。結合這些資訊我們可以斷定Java執行緒開啟過多，導致頻繁上下文切換，從而影響了整體效能。

為什麼系統的上下文切換是每秒800多萬，而 Java 程式中的某一個執行緒切換才15次左右？

系統上下文切換分為三種情況:

1、多工：在多工環境中，一個程式被切換出CPU，執行另外一個程式，這裡會發生上下文切換。

2、中斷處理：發生中斷時，硬體會切換上下文。在vmstat命令中是in

3、使用者和核心模式切換：當作業系統中需要在使用者模式和核心模式之間進行轉換時，需要進行上下文切換,比如進行系統函式呼叫。

Linux 為每個 CPU 維護了一個就緒佇列，將活躍程式按照優先順序和等待 CPU 的時間排序，然後選擇最需要 CPU 的程式，也就是優先順序最高和等待 CPU 時間最長的程式來執行。也就是vmstat命令中的r。

那麼，程式在什麼時候才會被排程到 CPU 上執行呢？

程式執行完終止了，它之前使用的 CPU 會釋放出來，這時再從就緒佇列中拿一個新的程式來執行
為了保證所有程式可以得到公平排程，CPU 時間被劃分為一段段的時間片，這些時間片被輪流分配給各個程式。當某個程式時間片耗盡了就會被系統掛起，切換到其它等待 CPU 的程式執行。
程式在系統資源不足時，要等待資源滿足後才可以執行，這時程式也會被掛起，並由系統排程其它程式執行。
當程式通過睡眠函式 sleep 主動掛起時，也會重新排程。
當有優先順序更高的程式執行時，為了保證高優先順序程式的執行，當前程式會被掛起，由高優先順序程式來執行。
發生硬體中斷時，CPU 上的程式會被中斷掛起，轉而執行核心中的中斷服務程式。

結合我們之前的內容分析，阻塞的就緒佇列是100左右，而我們的CPU只有4核，這部分原因造成的上下文切換就可能會相當高，再加上中斷次數是4000左右和系統的函式呼叫等，整個系統的上下文切換到800萬也不足為奇了。Java內部的執行緒切換才15次，是因為執行緒使用Thread.yield()來讓出CPU資源，但是CPU有可能繼續排程該執行緒，這個時候執行緒之間並沒有切換，這也是為什麼內部的某個執行緒切換次數並不是非常大的原因。

總結

本文模擬了常見的效能問題場景，分析瞭如何定位CPU100%、記憶體洩漏、死鎖、執行緒頻繁切換問題。分析問題我們需要做好兩件事，第一，掌握基本的原理，第二，藉助好工具。本文也列舉了分析問題的常用工具和命令，希望對你解決問題有所幫助。當然真正的線上環境可能十分複雜，並沒有模擬的環境那麼簡單，但是原理是一樣的，問題的表現也是類似的，我們重點抓住原理，活學活用，相信複雜的線上問題也可以順利解決。