處理過線上問題的同學基本上都會遇到系統突然運作緩慢，CPU 100%，以及Full GC次數過多的問題。當然，這些問題的最終導緻的直覺現象就是系統運作緩慢，并且有大量的報警。本文主要針對系統運作緩慢這一問題，提供該問題的排查思路，進而定位出問題的代碼點，進而提供解決該問題的思路。
對于線上系統突然産生的運作緩慢問題，如果該問題導緻線上系統不可用，那麼首先需要做的就是，導出jstack和記憶體資訊，然後重新開機系統，盡快保證系統的可用性。這種情況可能的原因主要有兩種：
代碼中某個位置讀取資料量較大，導緻系統記憶體耗盡，進而導緻Full GC次數過多，系統緩慢；
代碼中有比較耗CPU的操作，導緻CPU過高，系統運作緩慢；
相對來說，這是出現頻率最高的兩種線上問題，而且它們會直接導緻系統不可用。另外有幾種情況也會導緻某個功能運作緩慢，但是不至于導緻系統不可用：
代碼某個位置有阻塞性的操作，導緻該功能調用整體比較耗時，但出現是比較随機的；
某個線程由于某種原因而進入WAITING狀态，此時該功能整體不可用，但是無法複現；
由于鎖使用不當，導緻多個線程進入死鎖狀态，進而導緻系統整體比較緩慢。
對于這三種情況，通過檢視CPU和系統記憶體情況是無法檢視出具體問題的，因為它們相對來說都是具有一定阻塞性操作，CPU和系統記憶體使用情況都不高，但是功能卻很慢。下面我們就通過檢視系統日志來一步一步甄别上述幾種問題。
1. Full GC次數過多
相對來說，這種情況是最容易出現的，尤其是新功能上線時。對于Full GC較多的情況，其主要有如下兩個特征：
線上多個線程的CPU都超過了100%，通過jstack指令可以看到這些線程主要是垃圾回收線程
通過jstat指令監控GC情況，可以看到Full GC次數非常多，并且次數在不斷增加。
首先我們可以使用top指令檢視系統CPU的占用情況，如下是系統CPU較高的一個示例：
<code>top - 08:31:10 up 30 min, 0 users, load average: 0.73, 0.58, 0.34</code>
<code>KiB Mem: 2046460 total, 1923864 used, 122596 free, 14388 buffers</code>
<code>KiB Swap: 1048572 total, 0 used, 1048572 free. 1192352 cached Mem</code>
<code> PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND</code>
<code> 9 root 20 0 2557160 288976 15812 S 98.0 14.1 0:42.60 java</code>
可以看到，有一個Java程式此時CPU占用量達到了98.8%，此時我們可以複制該程序id9，并且使用如下指令檢視呢該程序的各個線程運作情況：
該程序下的各個線程運作情況如下：
<code>top - 08:31:16 up 30 min, 0 users, load average: 0.75, 0.59, 0.35</code>
<code>Threads: 11 total, 1 running, 10 sleeping, 0 stopped, 0 zombie</code>
<code>%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</code>
<code>KiB Mem: 2046460 total, 1924856 used, 121604 free, 14396 buffers</code>
<code>KiB Swap: 1048572 total, 0 used, 1048572 free. 1192532 cached Mem</code>
<code> PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND</code>
<code> 10 root 20 0 2557160 289824 15872 R 79.3 14.2 0:41.49 java</code>
<code> 11 root 20 0 2557160 289824 15872 S 13.2 14.2 0:06.78 java</code>
可以看到，在程序為9的Java程式中各個線程的CPU占用情況，接下來我們可以通過jstack指令檢視線程id為10的線程為什麼耗費CPU最高。需要注意的是，在jsatck指令展示的結果中，線程id都轉換成了十六進制形式。可以用如下指令檢視轉換結果，也可以找一個科學電腦進行轉換：
這裡列印結果說明該線程在jstack中的展現形式為0xa，通過jstack指令我們可以看到如下資訊：
<code>"main" #1 prio=5 os_prio=0 tid=0x00007f8718009800 nid=0xb runnable [0x00007f871fe41000]</code>
<code> java.lang.Thread.State: RUNNABLE</code>
<code> at com.aibaobei.chapter2.eg2.UserDemo.main(UserDemo.java:9)</code>
<code>"VM Thread" os_prio=0 tid=0x00007f871806e000 nid=0xa runnable</code>
這裡的VM Thread一行的最後顯示nid=0xa，這裡nid的意思就是作業系統線程id的意思。而VM Thread指的就是垃圾回收的線程。這裡我們基本上可以确定，目前系統緩慢的原因主要是垃圾回收過于頻繁，導緻GC停頓時間較長。我們通過如下指令可以檢視GC的情況：
可以看到，這裡FGC指的是Full GC數量，這裡高達6793，而且還在不斷增長。進而進一步證明了是由于記憶體溢出導緻的系統緩慢。那麼這裡确認了記憶體溢出，但是如何檢視你是哪些對象導緻的記憶體溢出呢，這個可以dump出記憶體日志，然後通過eclipse的mat工具進行檢視，如下是其展示的一個對象樹結構：
經過mat工具分析之後，我們基本上就能确定記憶體中主要是哪個對象比較消耗記憶體，然後找到該對象的建立位置，進行處理即可。這裡的主要是PrintStream最多，但是我們也可以看到，其記憶體消耗量隻有12.2%。也就是說，其還不足以導緻大量的Full GC，此時我們需要考慮另外一種情況，就是代碼或者第三方依賴的包中有顯示的System.gc()調用。這種情況我們檢視dump記憶體得到的檔案即可判斷，因為其會列印GC原因：
比如這裡第一次GC是由于System.gc()的顯示調用導緻的，而第二次GC則是JVM主動發起的。總結來說，對于Full GC次數過多，主要有以下兩種原因：
代碼中一次擷取了大量的對象，導緻記憶體溢出，此時可以通過eclipse的mat工具檢視記憶體中有哪些對象比較多；
記憶體占用不高，但是Full GC次數還是比較多，此時可能是顯示的 <code>System.gc()</code>調用導緻GC次數過多，這可以通過添加 <code>-XX:+DisableExplicitGC</code>來禁用JVM對顯示GC的響應。
2. CPU過高
在前面第一點中，我們講到，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行，檢視代碼中具體是什麼原因導緻計算量如此之高。
3. 不定期出現的接口耗時現象
對于這種情況，比較典型的例子就是，我們某個接口通路經常需要2~3s才能傳回。這是比較麻煩的一種情況，因為一般來說，其消耗的CPU不多，而且占用的記憶體也不高，也就是說，我們通過上述兩種方式進行排查是無法解決這種問題的。而且由于這樣的接口耗時比較大的問題是不定時出現的，這就導緻了我們在通過jstack指令即使得到了線程通路的堆棧資訊，我們也沒法判斷具體哪個線程是正在執行比較耗時操作的線程。
對于不定時出現的接口耗時比較嚴重的問題，我們的定位思路基本如下：首先找到該接口，通過壓測工具不斷加大通路力度，如果說該接口中有某個位置是比較耗時的，由于我們的通路的頻率非常高，那麼大多數的線程最終都将阻塞于該阻塞點，這樣通過多個線程具有相同的堆棧日志，我們基本上就可以定位到該接口中比較耗時的代碼的位置。如下是一個代碼中有比較耗時的阻塞操作通過壓測工具得到的線程堆棧日志：
<code>"http-nio-8080-exec-2" #29 daemon prio=5 os_prio=31 tid=0x00007fd08cb26000 nid=0x9603 waiting on condition [0x00007000031d5000]</code>
<code> java.lang.Thread.State: TIMED_WAITING (sleeping)</code>
<code> at java.lang.Thread.sleep(Native Method)</code>
<code> at java.lang.Thread.sleep(Thread.java:340)</code>
<code> at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)</code>
<code> at com.aibaobei.user.controller.UserController.detail(UserController.java:18)</code>
<code>"http-nio-8080-exec-3" #30 daemon prio=5 os_prio=31 tid=0x00007fd08cb27000 nid=0x6203 waiting on condition [0x00007000032d8000]</code>
<code>"http-nio-8080-exec-4" #31 daemon prio=5 os_prio=31 tid=0x00007fd08d0fa000 nid=0x6403 waiting on condition [0x00007000033db000]</code>
從上面的日志可以看你出，這裡有多個線程都阻塞在了UserController的第18行，說明這是一個阻塞點，也就是導緻該接口比較緩慢的原因。
4. 某個線程進入WAITING狀态
對于這種情況，這是比較罕見的一種情況，但是也是有可能出現的，而且由于其具有一定的“不可複現性”，因而我們在排查的時候是非常難以發現的。筆者曾經就遇到過類似的這種情況，具體的場景是，在使用CountDownLatch時，由于需要每一個并行的任務都執行完成之後才會喚醒主線程往下執行。而當時我們是通過CountDownLatch控制多個線程連接配接并導出使用者的gmail郵箱資料，這其中有一個線程連接配接上了使用者郵箱，但是連接配接被伺服器挂起了，導緻該線程一直在等待伺服器的響應。最終導緻我們的主線程和其餘幾個線程都處于WAITING狀态。
對于這樣的問題，檢視過jstack日志的讀者應該都知道，正常情況下，線上大多數線程都是處于TIMED_WAITING狀态，而我們這裡出問題的線程所處的狀态與其是一模一樣的，這就非常容易混淆我們的判斷。解決這個問題的思路主要如下：
通過grep在jstack日志中找出所有的處于 <code>TIMED_WAITING</code>狀态的線程，将其導出到某個檔案中，如a1.log，如下是一個導出的日志檔案示例：
等待一段時間之後，比如10s，再次對jstack日志進行grep，将其導出到另一個檔案，如a2.log，結果如下所示：
重複步驟2，待導出3~4個檔案之後，我們對導出的檔案進行對比，找出其中在這幾個檔案中一直都存在的使用者線程，這個線程基本上就可以确認是包含了處于等待狀态有問題的線程。因為正常的請求線程是不會在20~30s之後還是處于等待狀态的。
經過排查得到這些線程之後，我們可以繼續對其堆棧資訊進行排查，如果該線程本身就應該處于等待狀态，比如使用者建立的線程池中處于空閑狀态的線程，那麼這種線程的堆棧資訊中是不會包含使用者自定義的類的。這些都可以排除掉，而剩下的線程基本上就可以确認是我們要找的有問題的線程。通過其堆棧資訊，我們就可以得出具體是在哪個位置的代碼導緻該線程處于等待狀态了。
這裡需要說明的是，我們在判斷是否為使用者線程時，可以通過線程最前面的線程名來判斷，因為一般的架構的線程命名都是非正常範的，我們通過線程名就可以直接判斷得出該線程是某些架構中的線程，這種線程基本上可以排除掉。而剩餘的，比如上面的Thread-0，以及我們可以辨識的自定義線程名，這些都是我們需要排查的對象。
經過上面的方式進行排查之後，我們基本上就可以得出這裡的Thread-0就是我們要找的線程，通過檢視其堆棧資訊，我們就可以得到具體是在哪個位置導緻其處于等待狀态了。如下示例中則是在SyncTask的第8行導緻該線程進入等待了。
5. 死鎖
對于死鎖，這種情況基本上很容易發現，因為jstack可以幫助我們檢查死鎖，并且在日志中列印具體的死鎖線程資訊。如下是一個産生死鎖的一個jstack日志示例：
可以看到，在jstack日志的底部，其直接幫我們分析了日志中存在哪些死鎖，以及每個死鎖的線程堆棧資訊。這裡我們有兩個使用者線程分别在等待對方釋放鎖，而被阻塞的位置都是在ConnectTask的第5行，此時我們就可以直接定位到該位置，并且進行代碼分析，進而找到産生死鎖的原因。
6. 小結
本文主要講解了線上可能出現的五種導緻系統緩慢的情況，詳細分析了每種情況産生時的現象，已經根據現象我們可以通過哪些方式定位得到是這種原因導緻的系統緩慢。簡要的說，我們進行線上日志分析時，主要可以分為如下步驟：
通過 <code>top</code>指令檢視CPU情況，如果CPU比較高，則通過 <code>top-Hp<pid></code>指令檢視目前程序的各個線程運作情況，找出CPU過高的線程之後，将其線程id轉換為十六進制的表現形式，然後在jstack日志中檢視該線程主要在進行的工作。這裡又分為兩種情況
如果是正常的使用者線程，則通過該線程的堆棧資訊檢視其具體是在哪處使用者代碼處運作比較消耗CPU；
如果該線程是 <code>VMThread</code>，則通過 <code>jstat-gcutil<pid><period><times></code>指令監控目前系統的GC狀況，然後通過 <code>jmapdump:format=b,file=<filepath><pid></code>導出系統目前的記憶體資料。導出之後将記憶體情況放到eclipse的mat工具中進行分析即可得出記憶體中主要是什麼對象比較消耗記憶體，進而可以處理相關代碼；
如果通過 <code>top</code> 指令看到CPU并不高，并且系統記憶體占用率也比較低。此時就可以考慮是否是由于另外三種情況導緻的問題。具體的可以根據具體情況分析：
如果是接口調用比較耗時，并且是不定時出現，則可以通過壓測的方式加大阻塞點出現的頻率，進而通過 <code>jstack</code>檢視堆棧資訊，找到阻塞點；
如果是某個功能突然出現停滞的狀況，這種情況也無法複現，此時可以通過多次導出 <code>jstack</code>日志的方式對比哪些使用者線程是一直都處于等待狀态，這些線程就是可能存在問題的線程；
如果通過 <code>jstack</code>可以檢視到死鎖狀态，則可以檢查産生死鎖的兩個線程的具體阻塞點，進而處理相應的問題。
本文主要是提出了五種常見的導緻線上功能緩慢的問題，以及排查思路。當然，線上的問題出現的形式是多種多樣的，也不一定局限于這幾種情況，如果我們能夠仔細分析這些問題出現的場景，就可以根據具體情況具體分析，進而解決相應的問題。
來源：http://t.cn/EI9JdBu