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

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

概述

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

相關閱讀：

  1. 《效能診斷利器 JProfiler 快速入門和最佳實踐》：https://segmentfault.com/a/1190000017795841

模擬環境準備

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

參考

1、https://linux.die.net/man/1/pidstat

2、https://linux.die.net/man/8/vmstat

3、https://help.eclipse.org/2020-03/index.jsp?topic=/org.eclipse.mat.ui.help/welcome.html

4、https://www.linuxblogs.cn/articles/18120200.html

5、https://www.tutorialspoint.com/what-is-context-switching-in-operating-system

相關文章