教你如何排查Java系統(tǒng)運(yùn)行緩慢等問題 附詳細(xì)思路

前言

處理過線上問題的同學(xué)基本上都會(huì)遇到系統(tǒng)突然運(yùn)行緩慢，CPU 100%，以及Full GC次數(shù)過多的問題。當(dāng)然，這些問題的最終導(dǎo)致的直觀現(xiàn)象就是系統(tǒng)運(yùn)行緩慢，并且有大量的報(bào)警。

本文主要針對(duì)系統(tǒng)運(yùn)行緩慢這一問題，提供該問題的排查思路，從而定位出問題的代碼點(diǎn)，進(jìn)而提供解決該問題的思路。

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

• 代碼中某個(gè)位置讀取數(shù)據(jù)量較大，導(dǎo)致系統(tǒng)內(nèi)存耗盡，從而導(dǎo)致Full GC次數(shù)過多，系統(tǒng)緩慢；
• 代碼中有比較耗CPU的操作，導(dǎo)致CPU過高，系統(tǒng)運(yùn)行緩慢；

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

• 代碼某個(gè)位置有阻塞性的操作，導(dǎo)致該功能調(diào)用整體比較耗時(shí)，但出現(xiàn)是比較隨機(jī)的；
• 某個(gè)線程由于某種原因而進(jìn)入WAITING狀態(tài)，此時(shí)該功能整體不可用，但是無法復(fù)現(xiàn)；
• 由于鎖使用不當(dāng)，導(dǎo)致多個(gè)線程進(jìn)入死鎖狀態(tài)，從而導(dǎo)致系統(tǒng)整體比較緩慢。

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

Full GC次數(shù)過多

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

線上多個(gè)線程的CPU都超過了100%，通過jstack命令可以看到這些線程主要是垃圾回收線程通過jstat命令監(jiān)控GC情況，可以看到Full GC次數(shù)非常多，并且次數(shù)在不斷增加。

首先我們可以使用top命令查看系統(tǒng)CPU的占用情況，如下是系統(tǒng)CPU較高的一個(gè)示例：

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

可以看到，有一個(gè)Java程序此時(shí)CPU占用量達(dá)到了98.8%，此時(shí)我們可以復(fù)制該進(jìn)程id9，并且使用如下命令查看呢該進(jìn)程的各個(gè)線程運(yùn)行情況：

top -Hp 9

該進(jìn)程下的各個(gè)線程運(yùn)行情況如下：

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

可以看到，在進(jìn)程為9的Java程序中各個(gè)線程的CPU占用情況，接下來我們可以通過jstack命令查看線程id為10的線程為什么耗費(fèi)CPU最高。需要注意的是，在jsatck命令展示的結(jié)果中，線程id都轉(zhuǎn)換成了十六進(jìn)制形式?？梢杂萌缦旅畈榭崔D(zhuǎn)換結(jié)果，也可以找一個(gè)科學(xué)計(jì)算器進(jìn)行轉(zhuǎn)換：

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

這里打印結(jié)果說明該線程在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一行的最后顯示nid=0xa，這里nid的意思就是操作系統(tǒng)線程id的意思。而VM Thread指的就是垃圾回收的線程。這里我們基本上可以確定，當(dāng)前系統(tǒng)緩慢的原因主要是垃圾回收過于頻繁，導(dǎo)致GC停頓時(shí)間較長。我們通過如下命令可以查看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

可以看到，這里FGC指的是Full GC數(shù)量，這里高達(dá)6793，而且還在不斷增長。從而進(jìn)一步證實(shí)了是由于內(nèi)存溢出導(dǎo)致的系統(tǒng)緩慢。那么這里確認(rèn)了內(nèi)存溢出，但是如何查看你是哪些對(duì)象導(dǎo)致的內(nèi)存溢出呢，這個(gè)可以dump出內(nèi)存日志，然后通過eclipse的mat工具進(jìn)行查看，如下是其展示的一個(gè)對(duì)象樹結(jié)構(gòu)：

經(jīng)過mat工具分析之后，我們基本上就能確定內(nèi)存中主要是哪個(gè)對(duì)象比較消耗內(nèi)存，然后找到該對(duì)象的創(chuàng)建位置，進(jìn)行處理即可。這里的主要是PrintStream最多，但是我們也可以看到，其內(nèi)存消耗量只有12.2%。也就是說，其還不足以導(dǎo)致大量的Full GC，此時(shí)我們需要考慮另外一種情況，就是代碼或者第三方依賴的包中有顯示的System.gc()調(diào)用。這種情況我們查看dump內(nèi)存得到的文件即可判斷，因?yàn)槠鋾?huì)打印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是由于System.gc()的顯示調(diào)用導(dǎo)致的，而第二次GC則是JVM主動(dòng)發(fā)起的?？偨Y(jié)來說，對(duì)于Full GC次數(shù)過多，主要有以下兩種原因：

• 代碼中一次獲取了大量的對(duì)象，導(dǎo)致內(nèi)存溢出，此時(shí)可以通過eclipse的mat工具查看內(nèi)存中有哪些對(duì)象比較多；
• 內(nèi)存占用不高，但是Full GC次數(shù)還是比較多，此時(shí)可能是顯示的System.gc()調(diào)用導(dǎo)致GC次數(shù)過多，這可以通過添加-XX:+DisableExplicitGC來禁用JVM對(duì)顯示GC的響應(yīng)。

CPU過高

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

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

這里可以看到，在請(qǐng)求UserController的時(shí)候，由于該Controller進(jìn)行了一個(gè)比較耗時(shí)的調(diào)用，導(dǎo)致該線程的CPU一直處于100%。我們可以根據(jù)堆棧信息，直接定位到UserController的34行，查看代碼中具體是什么原因?qū)е掠?jì)算量如此之高。

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

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

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

"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)

從上面的日志可以看你出，這里有多個(gè)線程都阻塞在了UserController的第18行，說明這是一個(gè)阻塞點(diǎn)，也就是導(dǎo)致該接口比較緩慢的原因。

某個(gè)線程進(jìn)入WAITING狀態(tài)

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

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

通過grep在jstack日志中找出所有的處于TIMED_WAITING狀態(tài)的線程，將其導(dǎo)出到某個(gè)文件中，如a1.log，如下是一個(gè)導(dǎo)出的日志文件示例：

"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]

等待一段時(shí)間之后，比如10s，再次對(duì)jstack日志進(jìn)行g(shù)rep，將其導(dǎo)出到另一個(gè)文件，如a2.log，結(jié)果如下所示：

"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]

重復(fù)步驟2，待導(dǎo)出34個(gè)文件之后，我們對(duì)導(dǎo)出的文件進(jìn)行對(duì)比，找出其中在這幾個(gè)文件中一直都存在的用戶線程，這個(gè)線程基本上就可以確認(rèn)是包含了處于等待狀態(tài)有問題的線程。因?yàn)檎５恼?qǐng)求線程是不會(huì)在2030s之后還是處于等待狀態(tài)的。經(jīng)過排查得到這些線程之后，我們可以繼續(xù)對(duì)其堆棧信息進(jìn)行排查，如果該線程本身就應(yīng)該處于等待狀態(tài)，比如用戶創(chuàng)建的線程池中處于空閑狀態(tài)的線程，那么這種線程的堆棧信息中是不會(huì)包含用戶自定義的類的。這些都可以排除掉，而剩下的線程基本上就可以確認(rèn)是我們要找的有問題的線程。通過其堆棧信息，我們就可以得出具體是在哪個(gè)位置的代碼導(dǎo)致該線程處于等待狀態(tài)了。

這里需要說明的是，我們?cè)谂袛嗍欠駷橛脩艟€程時(shí)，可以通過線程最前面的線程名來判斷，因?yàn)橐话愕目蚣艿木€程命名都是非常規(guī)范的，我們通過線程名就可以直接判斷得出該線程是某些框架中的線程，這種線程基本上可以排除掉。而剩余的，比如上面的Thread-0，以及我們可以辨別的自定義線程名，這些都是我們需要排查的對(duì)象。

經(jīng)過上面的方式進(jìn)行排查之后，我們基本上就可以得出這里的Thread-0就是我們要找的線程，通過查看其堆棧信息，我們就可以得到具體是在哪個(gè)位置導(dǎo)致其處于等待狀態(tài)了。如下示例中則是在SyncTask的第8行導(dǎo)致該線程進(jìn)入等待了。

"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)

死鎖

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

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

小結(jié)

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

1.通過top命令查看CPU情況，如果CPU比較高，則通過top -Hp 命令查看當(dāng)前進(jìn)程的各個(gè)線程運(yùn)行情況，找出CPU過高的線程之后，將其線程id轉(zhuǎn)換為十六進(jìn)制的表現(xiàn)形式，然后在jstack日志中查看該線程主要在進(jìn)行的工作。這里又分為兩種情況:

• 如果是正常的用戶線程，則通過該線程的堆棧信息查看其具體是在哪處用戶代碼處運(yùn)行比較消耗CPU；
• 如果該線程是VM Thread，則通過jstat -gcutil <pid> <period> <times>命令監(jiān)控當(dāng)前系統(tǒng)的GC狀況，然后通過jmap dump:format=b,file=<filepath> <pid>導(dǎo)出系統(tǒng)當(dāng)前的內(nèi)存數(shù)據(jù)。導(dǎo)出之后將內(nèi)存情況放到eclipse的mat工具中進(jìn)行分析即可得出內(nèi)存中主要是什么對(duì)象比較消耗內(nèi)存，進(jìn)而可以處理相關(guān)代碼；

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

• 如果是接口調(diào)用比較耗時(shí)，并且是不定時(shí)出現(xiàn)，則可以通過壓測(cè)的方式加大阻塞點(diǎn)出現(xiàn)的頻率，從而通過jstack查看堆棧信息，找到阻塞點(diǎn)；
• 如果是某個(gè)功能突然出現(xiàn)停滯的狀況，這種情況也無法復(fù)現(xiàn)，此時(shí)可以通過多次導(dǎo)出jstack日志的方式對(duì)比哪些用戶線程是一直都處于等待狀態(tài)，這些線程就是可能存在問題的線程；
• 如果通過jstack可以查看到死鎖狀態(tài)，則可以檢查產(chǎn)生死鎖的兩個(gè)線程的具體阻塞點(diǎn)，從而處理相應(yīng)的問題。

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

以上就是如何排查Java系統(tǒng)運(yùn)行緩慢等問題的詳細(xì)思路的全部內(nèi)容，想要了解更多關(guān)于Java系統(tǒng)運(yùn)行緩慢等問題的資料，請(qǐng)關(guān)注W3Cschool其它相關(guān)文章！也希望大家以后能夠多多支持！