一次性搞清楚線上CPU100%，頻繁FullGC排查套路

當然，這些問題最終導致的直觀現象就是系統執行緩慢，並且有大量的報警。

本文主要針對系統執行緩慢這一問題，提供該問題的排查思路，從而定位出問題的程式碼點，進而提供解決該問題的思路。

對於線上系統突然產生的執行緩慢問題，如果該問題導致線上系統不可用，那麼首先需要做的就是，匯出 jstack 和記憶體資訊，然後重啟系統，儘快保證系統的可用性。

這種情況可能的原因主要有兩種：

• 程式碼中某個位置讀取資料量較大，導致系統記憶體耗盡，從而導致 Full GC 次數過多，系統緩慢。

• 程式碼中有比較耗 CPU 的操作，導致 CPU 過高，系統執行緩慢。

相對來說，這是出現頻率最高的兩種線上問題，而且它們會直接導致系統不可用。

另外有幾種情況也會導致某個功能執行緩慢，但是不至於導致系統不可用：

• 程式碼某個位置有阻塞性的操作，導致該功能呼叫整體比較耗時，但出現是比較隨機的。

• 某個執行緒由於某種原因而進入 WAITING 狀態，此時該功能整體不可用，但是無法復現。

• 由於鎖使用不當，導致多個執行緒進入死鎖狀態，從而導致系統整體比較緩慢。

對於這三種情況，透過檢視 CPU 和系統記憶體情況是無法查看出具體問題的，因為它們相對來說都是具有一定阻塞性操作，CPU 和系統記憶體使用情況都不高，但是功能卻很慢。

下麵我們就透過檢視系統日誌來一步一步甄別上述幾種問題。

相對來說，這種情況是最容易出現的，尤其是新功能上線時。

對於 Full GC 較多的情況，其主要有如下兩個特徵：

• 線上多個執行緒的 CPU 都超過了 100%，透過 jstack 命令可以看到這些執行緒主要是垃圾回收執行緒。

• 透過 jstat 命令監控 GC 情況，可以看到 Full GC 次數非常多，並且次數在不斷增加。

首先我們可以使用 top 命令檢視系統 CPU 的佔用情況，如下是系統 CPU 較高的一個示例：

top - 08:31:10 up 30 min,  0 users,  load average: 0.73, 0.58, 0.34
KiB Mem:   2046460 total,  1923864 used,   122596 free,    14388 buffers
KiB Swap:  1048572 total,        0 used,  1048572 free.  1192352 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
    9 root      20   0 2557160 288976  15812 S  98.0 14.1   0:42.60 java

可以看到，有一個 Java 程式此時 CPU 佔用量達到了 98.8%，此時我們可以複製該行程 id9，並且使用如下命令檢視該行程的各個執行緒執行情況：

top -Hp 9

該行程下的各個執行緒執行情況如下：

top - 08:31:16 up 30 min,  0 users,  load average: 0.75, 0.59, 0.35
Threads:  11 total,   1 running,  10 sleeping,   0 stopped,   0 zombie
%Cpu(s):  3.5 us,  0.6 sy,  0.0 ni, 95.9 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem:   2046460 total,  1924856 used,   121604 free,    14396 buffers
KiB Swap:  1048572 total,        0 used,  1048572 free.  1192532 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
   10 root      20   0 2557160 289824  15872 R 79.3 14.2   0:41.49 java
   11 root      20   0 2557160 289824  15872 S 13.2 14.2   0:06.78 java

可以看到，在行程為 9 的 Java 程式中各個執行緒的 CPU 佔用情況，接下來我們可以透過 jstack 命令檢視執行緒 id 為 10 的執行緒為什麼耗費 CPU 最高。

需要註意的是，在 jsatck 命令展示的結果中，執行緒 id 都轉換成了十六進位制形式。

可以用如下命令檢視轉換結果，也可以找一個科學計算器進行轉換：

root@a39de7e7934b:/# printf "%x\n" 10
a

這裡列印結果說明該執行緒在 jstack 中的展現形式為 0xa，透過 jstack 命令我們可以看到如下資訊：

"main" #1 prio=5 os_prio=0 tid=0x00007f8718009800 nid=0xb runnable [0x00007f871fe41000]
   java.lang.Thread.State: RUNNABLE
    at com.aibaobei.chapter2.eg2.UserDemo.main(UserDemo.java:9)

"VM Thread" os_prio=0 tid=0x00007f871806e000 nid=0xa runnable

這裡的 VM Thread 一行的最後顯示 nid=0xa，這裡 nid 的意思就是作業系統執行緒 id 的意思，而 VM Thread 指的就是垃圾回收的執行緒。

這裡我們基本上可以確定，當前系統緩慢的原因主要是垃圾回收過於頻繁，導致 GC 停頓時間較長。

我們透過如下命令可以檢視 GC 的情況：

root@8d36124607a0:/# jstat -gcutil 9 1000 10
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
  0.00   0.00   0.00  75.07  59.09  59.60   3259    0.919  6517    7.715    8.635
  0.00   0.00   0.00   0.08  59.09  59.60   3306    0.930  6611    7.822    8.752
  0.00   0.00   0.00   0.08  59.09  59.60   3351    0.943  6701    7.924    8.867
  0.00   0.00   0.00   0.08  59.09  59.60   3397    0.955  6793    8.029    8.984

可以看到，這裡 FGC 指的是 Full GC 數量，這裡高達 6793，而且還在不斷增長。從而進一步證實了是由於記憶體上限溢位導致的系統緩慢。

那麼這裡確認了記憶體上限溢位，但是如何檢視你是哪些物件導致的記憶體上限溢位呢，這個可以 Dump 出記憶體日誌，然後透過 Eclipse 的 Mat 工具進行檢視。

如下圖是其展示的一個物件樹結構：

經過 Mat 工具分析之後，我們基本上就能確定記憶體中主要是哪個物件比較消耗記憶體，然後找到該物件的建立位置，進行處理即可。

這裡主要是 PrintStream 最多，但是我們也可以看到，其記憶體消耗量只有 12.2%。

也就是說，其還不足以導致大量的 Full GC，此時我們需要考慮另外一種情況，就是程式碼或者第三方依賴的包中有顯示的 System.gc() 呼叫。

這種情況我們檢視 Dump 記憶體得到的檔案即可判斷，因為其會列印 GC 原因：

[Full GC (System.gc()) [Tenured: 262546K->262546K(349568K), 0.0014879 secs] 262546K->262546K(506816K), [Metaspace: 3109K->3109K(1056768K)], 0.0015151 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[GC (Allocation Failure) [DefNew: 2795K->0K(157248K), 0.0001504 secs][Tenured: 262546K->402K(349568K), 0.0012949 secs] 265342K->402K(506816K), [Metaspace: 3109K->3109K(1056768K)], 0.0014699 secs] [Times: user=0.00

比如這裡第一次 GC 是由於 System.gc() 的顯示呼叫導致的，而第二次 GC 則是 JVM 主動發起的。

總結來說，對於 Full GC 次數過多，主要有以下兩種原因：

• 程式碼中一次獲取了大量的物件，導致記憶體上限溢位，此時可以透過 Eclipse 的 Mat 工具檢視記憶體中有哪些物件比較多。

• 記憶體佔用不高，但是 Full GC 次數還是比較多，此時可能是顯示的 System.gc() 呼叫導致 GC 次數過多，這可以透過新增 -XX:+DisableExplicitGC 來禁用 JVM 對顯示 GC 的響應。

在前面第一點中，我們講到，CPU 過高可能是系統頻繁的進行 Full GC，導致系統緩慢。

而我們平常也肯定能遇到比較耗時的計算，導致 CPU 過高的情況，此時檢視方式其實與上面的非常類似。

首先我們透過 top 命令檢視當前 CPU 消耗過高的行程是哪個，從而得到行程 id；然後透過 top -Hp 來檢視該行程中有哪些執行緒 CPU 過高，一般超過 80% 就是比較高的，80% 左右是合理情況。

這樣我們就能得到 CPU 消耗比較高的執行緒 id。接著透過該執行緒 id 的十六進製表示在 jstack 日誌中檢視當前執行緒具體的堆疊資訊。

在這裡我們就可以區分導致 CPU 過高的原因具體是 Full GC 次數過多還是程式碼中有比較耗時的計算了。

如果是 Full GC 次數過多，那麼透過 jstack 得到的執行緒資訊會是類似於 VM Thread 之類的執行緒。

而如果是程式碼中有比較耗時的計算，那麼我們得到的就是一個執行緒的具體堆疊資訊。

如下是一個程式碼中有比較耗時的計算，導致 CPU 過高的執行緒資訊：

這裡可以看到，在請求 UserController 的時候，由於該 Controller 進行了一個比較耗時的呼叫，導致該執行緒的 CPU 一直處於 100%。

我們可以根據堆疊資訊，直接定位到 UserController 的 34 行，檢視程式碼中具體是什麼原因導致計算量如此之高。

對於這種情況，比較典型的例子就是，我們某個介面訪問經常需要 2~3s 才能傳回。

這是比較麻煩的一種情況，因為一般來說，其消耗的 CPU 不多，而且佔用的記憶體也不高，也就是說，我們透過上述兩種方式進行排查是無法解決這種問題的。

而且由於這樣的介面耗時比較大的問題是不定時出現的，這就導致了我們在透過 jstack 命令即使得到了執行緒訪問的堆疊資訊，我們也沒法判斷具體哪個執行緒是正在執行比較耗時操作的執行緒。

對於不定時出現的介面耗時比較嚴重的問題，我們的定位思路基本如下：首先找到該介面，透過壓測工具不斷加大訪問力度。

如果說該介面中有某個位置是比較耗時的，由於我們的訪問的頻率非常高，那麼大多數的執行緒最終都將阻塞於該阻塞點。

這樣透過多個執行緒具有相同的堆疊日誌，我們基本上就可以定位到該介面中比較耗時的程式碼的位置。

如下是一個程式碼中有比較耗時的阻塞操作透過壓測工具得到的執行緒堆疊日誌：

"http-nio-8080-exec-2" #29 daemon prio=5 os_prio=31 tid=0x00007fd08cb26000 nid=0x9603 waiting on condition [0x00007000031d5000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at java.lang.Thread.sleep(Thread.java:340)
    at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)
    at com.aibaobei.user.controller.UserController.detail(UserController.java:18)

"http-nio-8080-exec-3" #30 daemon prio=5 os_prio=31 tid=0x00007fd08cb27000 nid=0x6203 waiting on condition [0x00007000032d8000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at java.lang.Thread.sleep(Thread.java:340)
    at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)
    at com.aibaobei.user.controller.UserController.detail(UserController.java:18)

"http-nio-8080-exec-4" #31 daemon prio=5 os_prio=31 tid=0x00007fd08d0fa000 nid=0x6403 waiting on condition [0x00007000033db000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at java.lang.Thread.sleep(Thread.java:340)
    at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)
    at com.aibaobei.user.controller.UserController.detail(UserController.java:18)

從上面的日誌你可以看出，這裡有多個執行緒都阻塞在了 UserController 的第 18 行，說明這是一個阻塞點，也就是導致該介面比較緩慢的原因。

對於這種情況，這是比較罕見的一種情況，但是也是有可能出現的，而且由於其具有一定的“不可復現性”，因而我們在排查的時候是非常難以發現的。

筆者曾經就遇到過類似的這種情況，具體的場景是，在使用 CountDownLatch 時，由於需要每一個並行的任務都執行完成之後才會喚醒主執行緒往下執行。

而當時我們是透過 CountDownLatch 控制多個執行緒連線並匯出使用者的 Gmail 郵箱資料，這其中有一個執行緒連線上了使用者郵箱，但是連線被伺服器掛起了，導致該執行緒一直在等待伺服器的響應。

最終導致我們的主執行緒和其餘幾個執行緒都處於 WAITING 狀態。

對於這樣的問題，檢視過 jstack 日誌的讀者應該都知道，正常情況下，線上大多數執行緒都是處於 TIMED_WAITING 狀態。

而我們這裡出問題的執行緒所處的狀態與其是一模一樣的，這就非常容易混淆我們的判斷。

解決這個問題的思路主要如下：

①透過 grep 在 jstack 日誌中找出所有的處於 TIMED_WAITING 狀態的執行緒，將其匯出到某個檔案中，如 a1.log，如下是一個匯出的日誌檔案示例：

"Attach Listener" #13 daemon prio=9 os_prio=31 tid=0x00007fe690064000 nid=0xd07 waiting on condition [0x0000000000000000]
"DestroyJavaVM" #12 prio=5 os_prio=31 tid=0x00007fe690066000 nid=0x2603 waiting on condition [0x0000000000000000]
"Thread-0" #11 prio=5 os_prio=31 tid=0x00007fe690065000 nid=0x5a03 waiting on condition [0x0000700003ad4000]
"C1 CompilerThread3" #9 daemon prio=9 os_prio=31 tid=0x00007fe68c00a000 nid=0xa903 waiting on condition [0x0000000000000000]

②等待一段時間之後，比如 10s，再次對  jstack 日誌進行 grep，將其匯出到另一個檔案，如 a2.log，結果如下所示：

"DestroyJavaVM" #12 prio=5 os_prio=31 tid=0x00007fe690066000 nid=0x2603 waiting on condition [0x0000000000000000]
"Thread-0" #11 prio=5 os_prio=31 tid=0x00007fe690065000 nid=0x5a03 waiting on condition [0x0000700003ad4000]
"VM Periodic Task Thread" os_prio=31 tid=0x00007fe68d114000 nid=0xa803 waiting on condition

③重覆步驟 2，待匯出 3~4 個檔案之後，我們對匯出的檔案進行對比，找出其中在這幾個檔案中一直都存在的使用者執行緒。

這個執行緒基本上就可以確認是包含了處於等待狀態有問題的執行緒。因為正常的請求執行緒是不會在 20~30s 之後還是處於等待狀態的。

④經過排查得到這些執行緒之後，我們可以繼續對其堆疊資訊進行排查，如果該執行緒本身就應該處於等待狀態，比如使用者建立的執行緒池中處於空閑狀態的執行緒，那麼這種執行緒的堆疊資訊中是不會包含使用者自定義的類的。

這些都可以排除掉，而剩下的執行緒基本上就可以確認是我們要找的有問題的執行緒。

透過其堆疊資訊，我們就可以得出具體是在哪個位置的程式碼導致該執行緒處於等待狀態了。

這裡需要說明的是，我們在判斷是否為使用者執行緒時，可以透過執行緒最前面的執行緒名來判斷，因為一般的框架的執行緒命名都是非常規範的。

我們透過執行緒名就可以直接判斷得出該執行緒是某些框架中的執行緒，這種執行緒基本上可以排除掉。

而剩餘的，比如上面的 Thread-0，以及我們可以辨別的自定義執行緒名，這些都是我們需要排查的物件。

經過上面的方式進行排查之後，我們基本上就可以得出這裡的 Thread-0 就是我們要找的執行緒，透過檢視其堆疊資訊，我們就可以得到具體是在哪個位置導致其處於等待狀態了。

如下示例中則是在 SyncTask 的第 8 行導致該執行緒進入等待了：

"Thread-0" #11 prio=5 os_prio=31 tid=0x00007f9de08c7000 nid=0x5603 waiting on condition [0x0000700001f89000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:304)
    at com.aibaobei.chapter2.eg4.SyncTask.lambda$main$0(SyncTask.java:8)
    at com.aibaobei.chapter2.eg4.SyncTask$$Lambda$1/1791741888.run(Unknown Source)
    at java.lang.Thread.run(Thread.java:748)

對於死鎖，這種情況基本上很容易發現，因為 jstack 可以幫助我們檢查死鎖，並且在日誌中列印具體的死鎖執行緒資訊。

如下是一個產生死鎖的一個 jstack 日誌示例：

可以看到，在 jstack 日誌的底部，其直接幫我們分析了日誌中存在哪些死鎖，以及每個死鎖的執行緒堆疊資訊。

這裡我們有兩個使用者執行緒分別在等待對方釋放鎖，而被阻塞的位置都是在 ConnectTask 的第 5 行，此時我們就可以直接定位到該位置，並且進行程式碼分析，從而找到產生死鎖的原因。

本文主要講解了線上可能出現的五種導致系統緩慢的情況，詳細分析了每種情況產生時的現象，已經根據現象我們可以透過哪些方式定位得到是這種原因導致的系統緩慢。

簡要的說，我們進行線上日誌分析時，主要可以分為如下步驟：

①透過 top 命令檢視 CPU 情況，如果 CPU 比較高，則透過 top -Hp 命令檢視當前行程的各個執行緒執行情況。

找出 CPU 過高的執行緒之後，將其執行緒 id 轉換為十六進位制的表現形式，然後在 jstack 日誌中檢視該執行緒主要在進行的工作。

這裡又分為兩種情況：

• 如果是正常的使用者執行緒，則透過該執行緒的堆疊資訊檢視其具體是在哪處使用者程式碼處執行比較消耗 CPU。

• 如果該執行緒是 VM Thread，則透過 jstat -gcutil 命令監控當前系統的 GC 狀況。

  然後透過 jmap dump:format=b,file= 匯出系統當前的記憶體資料。

  匯出之後將記憶體情況放到 Eclipse 的 Mat 工具中進行分析即可得出記憶體中主要是什麼物件比較消耗記憶體，進而可以處理相關程式碼。

②如果透過 top 命令看到 CPU 並不高，並且系統記憶體佔用率也比較低。此時就可以考慮是否是由於另外三種情況導致的問題。

具體的可以根據具體情況分析：

• 如果是介面呼叫比較耗時，並且是不定時出現，則可以透過壓測的方式加大阻塞點出現的頻率，從而透過 jstack 檢視堆疊資訊，找到阻塞點。

• 如果是某個功能突然出現停滯的狀況，這種情況也無法復現，此時可以透過多次匯出 jstack 日誌的方式對比哪些使用者執行緒是一直都處於等待狀態，這些執行緒就是可能存在問題的執行緒。

• 如果透過 jstack 可以檢視到死鎖狀態，則可以檢查產生死鎖的兩個執行緒的具體阻塞點，從而處理相應的問題。

本文主要是提出了五種常見的導致線上功能緩慢的問題，以及排查思路。當然，線上的問題出現的形式是多種多樣的，也不一定侷限於這幾種情況。

如果我們能夠仔細分析這些問題出現的場景，就可以根據具體情況具體分析，從而解決相應的問題。

朋友會在“發現-看一看”看到你“在看”的內容

確定