這幾種常見的 JVM 調優場景,你知道嗎?

語言: CN / TW / HK

假定你已經瞭解了執行時的資料區域和常用的垃圾回收演算法,也瞭解了Hotspot支援的垃圾回收器。

一、cpu佔用過高

cpu佔用過高要分情況討論,是不是業務上在搞活動,突然有大批的流量進來,而且活動結束後cpu佔用率就下降了,如果是這種情況其實可以不用太關心,因為請求越多,需要處理的執行緒數越多,這是正常的現象。

話說回來,如果你的伺服器配置本身就差,cpu也只有一個核心,這種情況,稍微多一點流量就真的能夠把你的cpu資源耗盡,這時應該考慮先把配置提升吧。

第二種情況,cpu佔用率長期過高,這種情況下可能是你的程式有那種迴圈次數超級多的程式碼,甚至是出現死迴圈了。排查步驟如下:

(1)用top命令檢視cpu佔用情況

這樣就可以定位出cpu過高的程序。在linux下,top命令獲得的程序號和jps工具獲得的vmid是相同的:

(2)用top -Hp命令檢視執行緒的情況

可以看到是執行緒id為7287這個執行緒一直在佔用cpu

(3)把執行緒號轉換為16進位制

[root@localhost ~]# printf "%x" 7287
1c77

記下這個16進位制的數字,下面我們要用

(4)用jstack工具檢視執行緒棧情況

[root@localhost ~]# jstack 7268 | grep 1c77 -A 10
"http-nio-8080-exec-2" #16 daemon prio=5 os_prio=0 tid=0x00007fb66ce81000 nid=0x1c77 runnable [0x00007fb639ab9000]
   java.lang.Thread.State: RUNNABLE
 at com.spareyaya.jvm.service.EndlessLoopService.service(EndlessLoopService.java:19)
 at com.spareyaya.jvm.controller.JVMController.endlessLoop(JVMController.java:30)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 at java.lang.reflect.Method.invoke(Method.java:498)
 at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:190)
 at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:138)
 at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:105)

通過jstack工具輸出現在的執行緒棧,再通過grep命令結合上一步拿到的執行緒16進位制的id定位到這個執行緒的執行情況,其中jstack後面的7268是第(1)步定位到的程序號,grep後面的是(2)、(3)步定位到的執行緒號。

從輸出結果可以看到這個執行緒處於執行狀態,在執行 com.spareyaya.jvm.service.EndlessLoopService.service 這個方法,程式碼行號是19行,這樣就可以去到程式碼的19行,找到其所在的程式碼塊,看看是不是處於迴圈中,這樣就定位到了問題。

二、死鎖

死鎖並沒有第一種場景那麼明顯,web應用肯定是多執行緒的程式,它服務於多個請求,程式發生死鎖後,死鎖的執行緒處於等待狀態( WAITINGTIMED_WAITING ),等待狀態的執行緒不佔用cpu,消耗的記憶體也很有限,而表現上可能是請求沒法進行,最後超時了。在死鎖情況不多的時候,這種情況不容易被發現。

可以使用jstack工具來檢視

(1)jps檢視java程序

[root@localhost ~]# jps -l
8737 sun.tools.jps.Jps
8682 jvm-0.0.1-SNAPSHOT.jar

(2)jstack檢視死鎖問題

由於web應用往往會有很多工作執行緒,特別是在高併發的情況下執行緒數更多,於是這個命令的輸出內容會十分多。jstack最大的好處就是會把產生死鎖的資訊(包含是什麼執行緒產生的)輸出到最後,所以我們只需要看最後的內容就行了

Java stack information for the threads listed above:
===================================================
"Thread-4":
 at com.spareyaya.jvm.service.DeadLockService.service2(DeadLockService.java:35)
 - waiting to lock <0x00000000f5035ae0> (a java.lang.Object)
 - locked <0x00000000f5035af0> (a java.lang.Object)
 at com.spareyaya.jvm.controller.JVMController.lambda$deadLock$1(JVMController.java:41)
 at com.spareyaya.jvm.controller.JVMController$$Lambda$457/1776922136.run(Unknown Source)
 at java.lang.Thread.run(Thread.java:748)
"Thread-3":
 at com.spareyaya.jvm.service.DeadLockService.service1(DeadLockService.java:27)
 - waiting to lock <0x00000000f5035af0> (a java.lang.Object)
 - locked <0x00000000f5035ae0> (a java.lang.Object)
 at com.spareyaya.jvm.controller.JVMController.lambda$deadLock$0(JVMController.java:37)
 at com.spareyaya.jvm.controller.JVMController$$Lambda$456/474286897.run(Unknown Source)
 at java.lang.Thread.run(Thread.java:748)

Found 1 deadlock.

發現了一個死鎖,原因也一目瞭然。

三、記憶體洩漏

我們都知道,java和c++的最大區別是前者會自動收回不再使用的記憶體,後者需要程式設計師手動釋放。在c++中,如果我們忘記釋放記憶體就會發生記憶體洩漏。但是,不要以為jvm幫我們回收了記憶體就不會出現記憶體洩漏。

程式發生記憶體洩漏後,程序的可用記憶體會慢慢變少,最後的結果就是丟擲OOM錯誤。發生OOM錯誤後可能會想到是記憶體不夠大,於是把-Xmx引數調大,然後重啟應用。這麼做的結果就是,過了一段時間後,OOM依然會出現。最後無法再調大最大堆記憶體了,結果就是隻能每隔一段時間重啟一下應用。

記憶體洩漏的另一個可能的表現是請求的響應時間變長了。這是因為頻繁發生的GC會暫停其它所有執行緒( Stop The World )造成的。

為了模擬這個場景,使用了以下的程式

import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;

public class Main {

    public static void main(String[] args) {
        Main main = new Main();
        while (true) {
            try {
                Thread.sleep(1);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
            main.run();
        }
    }

    private void run() {
        ExecutorService executorService = Executors.newCachedThreadPool();
        for (int i = 0; i < 10; i++) {
            executorService.execute(() -> {
                // do something...
            });
        }
    }
}

執行引數是 -Xms20m -Xmx20m -XX:+PrintGC ,把可用記憶體調小一點,並且在發生gc時輸出資訊,執行結果如下

[GC (Allocation Failure)  12776K->10840K(18432K), 0.0309510 secs]
[GC (Allocation Failure)  13400K->11520K(18432K), 0.0333385 secs]
[GC (Allocation Failure)  14080K->12168K(18432K), 0.0332409 secs]
[GC (Allocation Failure)  14728K->12832K(18432K), 0.0370435 secs]
[Full GC (Ergonomics)  12832K->12363K(18432K), 0.1942141 secs]
[Full GC (Ergonomics)  14923K->12951K(18432K), 0.1607221 secs]
[Full GC (Ergonomics)  15511K->13542K(18432K), 0.1956311 secs]
...
[Full GC (Ergonomics)  16382K->16381K(18432K), 0.1734902 secs]
[Full GC (Ergonomics)  16383K->16383K(18432K), 0.1922607 secs]
[Full GC (Ergonomics)  16383K->16383K(18432K), 0.1824278 secs]
[Full GC (Allocation Failure)  16383K->16383K(18432K), 0.1710382 secs]
[Full GC (Ergonomics)  16383K->16382K(18432K), 0.1829138 secs]
[Full GC (Ergonomics) Exception in thread "main"  16383K->16382K(18432K), 0.1406222 secs]
[Full GC (Allocation Failure)  16382K->16382K(18432K), 0.1392928 secs]
[Full GC (Ergonomics)  16383K->16382K(18432K), 0.1546243 secs]
[Full GC (Ergonomics)  16383K->16382K(18432K), 0.1755271 secs]
[Full GC (Ergonomics)  16383K->16382K(18432K), 0.1699080 secs]
[Full GC (Allocation Failure)  16382K->16382K(18432K), 0.1697982 secs]
[Full GC (Ergonomics)  16383K->16382K(18432K), 0.1851136 secs]
[Full GC (Allocation Failure)  16382K->16382K(18432K), 0.1655088 secs]
java.lang.OutOfMemoryError: Java heap space

可以看到雖然一直在gc,佔用的記憶體卻越來越多,說明程式有的物件無法被回收。但是上面的程式物件都是定義在方法內的,屬於區域性變數,區域性變數在方法執行結果後,所引用的物件在gc時應該被回收啊,但是這裡明顯沒有。

為了找出到底是哪些物件沒能被回收,我們加上執行引數 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=heap.bin ,意思是發生OOM時把堆記憶體資訊dump出來。執行程式直至異常,於是得到 heap.dump 檔案,然後我們藉助eclipse的MAT外掛來分析,如果沒有安裝需要先安裝。

然後 File->Open Heap Dump... ,然後選擇剛才 dump 出來的檔案,選擇 Leak Suspects

MAT會列出所有可能發生記憶體洩漏的物件

可以看到居然有 21260 個Thread物件,3386個 ThreadPoolExecutor 物件,如果你去看一下 java.util.concurrent.ThreadPoolExecutor 的原始碼,可以發現執行緒池為了複用執行緒,會不斷地等待新的任務,執行緒也不會回收,需要呼叫其 shutdown 方法才能讓執行緒池執行完任務後停止。

其實執行緒池定義成區域性變數,好的做法是設定成單例。

上面只是其中一種處理方法

在線上的應用,記憶體往往會設定得很大,這樣發生OOM再把記憶體快照dump出來的檔案就會很大,可能大到在本地的電腦中已經無法分析了(因為記憶體不足夠開啟這個dump檔案)。這裡介紹另一種處理辦法:

(1)用jps定位到程序號

C:\Users\spareyaya\IdeaProjects\maven-project\target\classes\org\example\net>jps -l
24836 org.example.net.Main
62520 org.jetbrains.jps.cmdline.Launcher
129980 sun.tools.jps.Jps
136028 org.jetbrains.jps.cmdline.Launcher

因為已經知道了是哪個應用發生了OOM,這樣可以直接用jps找到程序號 135988

(2)用jstat分析gc活動情況

jstat是一個統計java程序記憶體使用情況和gc活動的工具,引數可以有很多,可以通過 jstat -help 檢視所有引數以及含義

C:\Users\spareyaya\IdeaProjects\maven-project\target\classes\org\example\net>jstat -gcutil -t -h8 24836 1000
Timestamp         S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
           29.1  32.81   0.00  23.48  85.92  92.84  84.13     14    0.339     0    0.000    0.339
           30.1  32.81   0.00  78.12  85.92  92.84  84.13     14    0.339     0    0.000    0.339
           31.1   0.00   0.00  22.70  91.74  92.72  83.71     15    0.389     1    0.233    0.622

上面是命令意思是輸出gc的情況,輸出時間,每8行輸出一個行頭資訊,統計的程序號是 24836 ,每1000毫秒輸出一次資訊。

輸出資訊是 Timestamp 是距離jvm啟動的時間,S0、S1、E是新生代的兩個 SurvivorEden ,O是老年代區,M是 Metaspace ,CCS使用壓縮比例,YGC和YGCT分別是新生代gc的次數和時間, FGCFGCT 分別是老年代gc的次數和時間,GCT是gc的總時間。雖然發生了gc,但是老年代記憶體佔用率根本沒下降,說明有的物件沒法被回收(當然也不排除這些物件真的是有用)。

(3)用jmap工具dump出記憶體快照

jmap可以把指定java程序的記憶體快照dump出來,效果和第一種處理辦法一樣,不同的是它不用等OOM就可以做到,而且dump出來的快照也會小很多。

jmap -dump:live,format=b,file=heap.bin 24836

這時會得到 heap.bin 的記憶體快照檔案,然後就可以用eclipse來分析了。

四、總結

以上三種嚴格地說還算不上jvm的調優,只是用了jvm工具把程式碼中存在的問題找了出來。我們進行jvm的主要目的是儘量減少停頓時間,提高系統的吞吐量。

但是如果我們沒有對系統進行分析就盲目去設定其中的引數,可能會得到更壞的結果,jvm發展到今天,各種預設的引數可能是實驗室的人經過多次的測試來做平衡的,適用大多數的應用場景。

如果你認為你的jvm確實有調優的必要,也務必要取樣分析,最後還得慢慢多次調節,才有可能得到更優的效果。