平時碰到系統(tǒng)CPU飆高和頻繁GC，你會怎么排查？

處理過線上問題的同學基本上都會遇到系統(tǒng)突然運行緩慢，CPU 100%，以及Full GC次數(shù)過多的問題。當然，這些問題的最終導致的直觀現(xiàn)象就是系統(tǒng)運行緩慢，并且有大量的報警。本文主要針對系統(tǒng)運行緩慢這一問題，提供該問題的排查思路，從而定位出問題的代碼點，進而提供解決該問題的思路。

對于線上系統(tǒng)突然產生的運行緩慢問題，如果該問題導致線上系統(tǒng)不可用，那么首先需要做的就是，導出jstack和內存信息，然后重啟系統(tǒng)，盡快保證系統(tǒng)的可用性。這種情況可能的原因主要有兩種：

• 代碼中某個位置讀取數(shù)據(jù)量較大，導致系統(tǒng)內存耗盡，從而導致Full GC次數(shù)過多，系統(tǒng)緩慢；

• 代碼中有比較耗CPU的操作，導致CPU過高，系統(tǒng)運行緩慢；

相對來說，這是出現(xiàn)頻率最高的兩種線上問題，而且它們會直接導致系統(tǒng)不可用。另外有幾種情況也會導致某個功能運行緩慢，但是不至于導致系統(tǒng)不可用：

• 代碼某個位置有阻塞性的操作，導致該功能調用整體比較耗時，但出現(xiàn)是比較隨機的；

• 某個線程由于某種原因而進入WAITING狀態(tài)，此時該功能整體不可用，但是無法復現(xiàn)；

• 由于鎖使用不當，導致多個線程進入死鎖狀態(tài)，從而導致系統(tǒng)整體比較緩慢。

對于這三種情況，通過查看CPU和系統(tǒng)內存情況是無法查看出具體問題的，因為它們相對來說都是具有一定阻塞性操作，CPU和系統(tǒng)內存使用情況都不高，但是功能卻很慢。下面我們就通過查看系統(tǒng)日志來一步一步甄別上述幾種問題。

1. Full GC次數(shù)過多

相對來說，這種情況是最容易出現(xiàn)的，尤其是新功能上線時。對于Full GC較多的情況，其主要有如下兩個特征：

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

• 通過jstat命令監(jiān)控GC情況，可以看到Full GC次數(shù)非常多，并且次數(shù)在不斷增加。

首先我們可以使用top命令查看系統(tǒng)CPU的占用情況，如下是系統(tǒng)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都轉換成了十六進制形式?？梢杂萌缦旅畈榭崔D換結果，也可以找一個科學計算器進行轉換：

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

這里打印結果說明該線程在jstack中的展現(xiàn)形式為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的意思就是操作系統(tǒng)線程id的意思。而VM Thread指的就是垃圾回收的線程。這里我們基本上可以確定，當前系統(tǒng)緩慢的原因主要是垃圾回收過于頻繁，導致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數(shù)量，這里高達6793，而且還在不斷增長。從而進一步證實了是由于內存溢出導致的系統(tǒng)緩慢。那么這里確認了內存溢出，但是如何查看你是哪些對象導致的內存溢出呢，這個可以dump出內存日志，然后通過eclipse的mat工具進行查看，如下是其展示的一個對象樹結構：

經過mat工具分析之后，我們基本上就能確定內存中主要是哪個對象比較消耗內存，然后找到該對象的創(chuàng)建位置，進行處理即可。這里的主要是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

2. CPU過高

在前面第一點中，我們講到，CPU過高可能是系統(tǒng)頻繁的進行Full GC，導致系統(tǒng)緩慢。而我們平常也肯能遇到比較耗時的計算，導致CPU過高的情況，此時查看方式其實與上面的非常類似。首先我們通過top命令查看當前CPU消耗過高的進程是哪個，從而得到進程id；然后通過top -Hp來查看該進程中有哪些線程CPU過高，一般超過80%就是比較高的，80%左右是合理情況。這樣我們就能得到CPU消耗比較高的線程id。接著通過該線程id的十六進制表示在jstack日志中查看當前線程具體的堆棧信息。

在這里我們就可以區(qū)分導致CPU過高的原因具體是Full GC次數(shù)過多還是代碼中有比較耗時的計算了。如果是Full GC次數(shù)過多，那么通過jstack得到的線程信息會是類似于VM Thread之類的線程，而如果是代碼中有比較耗時的計算，那么我們得到的就是一個線程的具體堆棧信息。如下是一個代碼中有比較耗時的計算，導致CPU過高的線程信息：

這里可以看到，在請求UserController的時候，由于該Controller進行了一個比較耗時的調用，導致該線程的CPU一直處于100%。我們可以根據(jù)堆棧信息，直接定位到UserController的34行，查看代碼中具體是什么原因導致計算量如此之高。

3. 不定期出現(xiàn)的接口耗時現(xiàn)象

對于這種情況，比較典型的例子就是，我們某個接口訪問經常需要2~3s才能返回。這是比較麻煩的一種情況，因為一般來說，其消耗的CPU不多，而且占用的內存也不高，也就是說，我們通過上述兩種方式進行排查是無法解決這種問題的。而且由于這樣的接口耗時比較大的問題是不定時出現(xiàn)的，這就導致了我們在通過jstack命令即使得到了線程訪問的堆棧信息，我們也沒法判斷具體哪個線程是正在執(zhí)行比較耗時操作的線程。

對于不定時出現(xiàn)的接口耗時比較嚴重的問題，我們的定位思路基本如下：首先找到該接口，通過壓測工具不斷加大訪問力度，如果說該接口中有某個位置是比較耗時的，由于我們的訪問的頻率非常高，那么大多數(shù)的線程最終都將阻塞于該阻塞點，這樣通過多個線程具有相同的堆棧日志，我們基本上就可以定位到該接口中比較耗時的代碼的位置。如下是一個代碼中有比較耗時的阻塞操作通過壓測工具得到的線程堆棧日志：

"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=31tid=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行，說明這是一個阻塞點，也就是導致該接口比較緩慢的原因。

4. 某個線程進入WAITING狀態(tài)

對于這種情況，這是比較罕見的一種情況，但是也是有可能出現(xiàn)的，而且由于其具有一定的“不可復現(xiàn)性”，因而我們在排查的時候是非常難以發(fā)現(xiàn)的。筆者曾經就遇到過類似的這種情況，具體的場景是，在使用CountDownLatch時，由于需要每一個并行的任務都執(zhí)行完成之后才會喚醒主線程往下執(zhí)行。而當時我們是通過CountDownLatch控制多個線程連接并導出用戶的gmail郵箱數(shù)據(jù)，這其中有一個線程連接上了用戶郵箱，但是連接被服務器掛起了，導致該線程一直在等待服務器的響應。最終導致我們的主線程和其余幾個線程都處于WAITING狀態(tài)。

對于這樣的問題，查看過jstack日志的讀者應該都知道，正常情況下，線上大多數(shù)線程都是處于TIMED_WAITING狀態(tài)，而我們這里出問題的線程所處的狀態(tài)與其是一模一樣的，這就非常容易混淆我們的判斷。解決這個問題的思路主要如下：

• 通過grep在jstack日志中找出所有的處于 TIMED_WAITING狀態(tài)的線程，將其導出到某個文件中，如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個文件之后，我們對導出的文件進行對比，找出其中在這幾個文件中一直都存在的用戶線程，這個線程基本上就可以確認是包含了處于等待狀態(tài)有問題的線程。因為正常的請求線程是不會在20~30s之后還是處于等待狀態(tài)的。

• 經過排查得到這些線程之后，我們可以繼續(xù)對其堆棧信息進行排查，如果該線程本身就應該處于等待狀態(tài)，比如用戶創(chuàng)建的線程池中處于空閑狀態(tài)的線程，那么這種線程的堆棧信息中是不會包含用戶自定義的類的。這些都可以排除掉，而剩下的線程基本上就可以確認是我們要找的有問題的線程。通過其堆棧信息，我們就可以得出具體是在哪個位置的代碼導致該線程處于等待狀態(tài)了。

這里需要說明的是，我們在判斷是否為用戶線程時，可以通過線程最前面的線程名來判斷，因為一般的框架的線程命名都是非常規(guī)范的，我們通過線程名就可以直接判斷得出該線程是某些框架中的線程，這種線程基本上可以排除掉。而剩余的，比如上面的Thread-0，以及我們可以辨別的自定義線程名，這些都是我們需要排查的對象。

經過上面的方式進行排查之后，我們基本上就可以得出這里的Thread-0就是我們要找的線程，通過查看其堆棧信息，我們就可以得到具體是在哪個位置導致其處于等待狀態(tài)了。如下示例中則是在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)

5. 死鎖

對于死鎖，這種情況基本上很容易發(fā)現(xiàn)，因為jstack可以幫助我們檢查死鎖，并且在日志中打印具體的死鎖線程信息。如下是一個產生死鎖的一個jstack日志示例：

可以看到，在jstack日志的底部，其直接幫我們分析了日志中存在哪些死鎖，以及每個死鎖的線程堆棧信息。這里我們有兩個用戶線程分別在等待對方釋放鎖，而被阻塞的位置都是在ConnectTask的第5行，此時我們就可以直接定位到該位置，并且進行代碼分析，從而找到產生死鎖的原因。

6. 小結

本文主要講解了線上可能出現(xiàn)的五種導致系統(tǒng)緩慢的情況，詳細分析了每種情況產生時的現(xiàn)象，已經根據(jù)現(xiàn)象我們可以通過哪些方式定位得到是這種原因導致的系統(tǒng)緩慢。簡要的說，我們進行線上日志分析時，主要可以分為如下步驟：

• 通過 top命令查看CPU情況，如果CPU比較高，則通過 top-Hp<pid>命令查看當前進程的各個線程運行情況，找出CPU過高的線程之后，將其線程id轉換為十六進制的表現(xiàn)形式，然后在jstack日志中查看該線程主要在進行的工作。這里又分為兩種情況

• 如果是正常的用戶線程，則通過該線程的堆棧信息查看其具體是在哪處用戶代碼處運行比較消耗CPU；

• 如果該線程是 VMThread，則通過 jstat-gcutil<pid><period><times>命令監(jiān)控當前系統(tǒng)的GC狀況，然后通過 jmapdump:format=b,file=<filepath><pid>導出系統(tǒng)當前的內存數(shù)據(jù)。導出之后將內存情況放到eclipse的mat工具中進行分析即可得出內存中主要是什么對象比較消耗內存，進而可以處理相關代碼；

• 如果通過 top 命令看到CPU并不高，并且系統(tǒng)內存占用率也比較低。此時就可以考慮是否是由于另外三種情況導致的問題。具體的可以根據(jù)具體情況分析：

• 如果是接口調用比較耗時，并且是不定時出現(xiàn)，則可以通過壓測的方式加大阻塞點出現(xiàn)的頻率，從而通過 jstack查看堆棧信息，找到阻塞點；

• 如果是某個功能突然出現(xiàn)停滯的狀況，這種情況也無法復現(xiàn)，此時可以通過多次導出 jstack日志的方式對比哪些用戶線程是一直都處于等待狀態(tài)，這些線程就是可能存在問題的線程；

• 如果通過 jstack可以查看到死鎖狀態(tài)，則可以檢查產生死鎖的兩個線程的具體阻塞點，從而處理相應的問題。

本文主要是提出了五種常見的導致線上功能緩慢的問題，以及排查思路。當然，線上的問題出現(xiàn)的形式是多種多樣的，也不一定局限于這幾種情況，如果我們能夠仔細分析這些問題出現(xiàn)的場景，就可以根據(jù)具體情況具體分析，從而解決相應的問題。

有需要的讀者朋友們可以加入Java架構技術交流Q群3 2 8 9 9 3 8 1 9即可獲取資料

還可以和小伙伴們一起探討面試時的問題與技術上的心得