系統運行緩慢，CPU 100%，以及Full GC次數過多問題的排查思路

       處理過線上問題的同窗基本上都會遇到系統忽然運行緩慢，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較高的一個示例：

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的響應。

2. CPU太高

       在前面第一點中，咱們講到，CPU太高多是系統頻繁的進行Full GC，致使系統緩慢。而咱們日常也肯能遇到比較耗時的計算，致使CPU太高的狀況，此時查看方式其實與上面的很是相似。首先咱們經過top命令查看當前CPU消耗太高的進程是哪一個，從而獲得進程id；而後經過top -Hp <pid>來查看該進程中有哪些線程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命令即便獲得了線程訪問的堆棧信息，咱們也無法判斷具體哪一個線程是正在執行比較耗時操做的線程。

       對於不定時出現的接口耗時比較嚴重的問題，咱們的定位思路基本以下：首先找到該接口，經過壓測工具不斷加大訪問力度，若是說該接口中有某個位置是比較耗時的，因爲咱們的訪問的頻率很是高，那麼大多數的線程最終都將阻塞於該阻塞點，這樣經過多個線程具備相同的堆棧日誌，咱們基本上就能夠定位到該接口中比較耗時的代碼的位置。以下是一個代碼中有比較耗時的阻塞操做經過壓測工具獲得的線程堆棧日誌：

"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行，說明這是一個阻塞點，也就是致使該接口比較緩慢的緣由。

4. 某個線程進入WAITING狀態

       對於這種狀況，這是比較罕見的一種狀況，可是也是有可能出現的，並且因爲其具備必定的「不可復現性」，於是咱們在排查的時候是很是難以發現的。筆者曾經就遇到過相似的這種狀況，具體的場景是，在使用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)

5. 死鎖

       對於死鎖，這種狀況基本上很容易發現，由於jstack能夠幫助咱們檢查死鎖，而且在日誌中打印具體的死鎖線程信息。以下是一個產生死鎖的一個jstack日誌示例：

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

6. 小結

       本文主要講解了線上可能出現的五種致使系統緩慢的狀況，詳細分析了每種狀況產生時的現象，已經根據現象咱們能夠經過哪些方式定位獲得是這種緣由致使的系統緩慢。簡要的說，咱們進行線上日誌分析時，主要能夠分爲以下步驟：

• 經過top命令查看CPU狀況，若是CPU比較高，則經過top -Hp <pid>命令查看當前進程的各個線程運行狀況，找出CPU太高的線程以後，將其線程id轉換爲十六進制的表現形式，而後在jstack日誌中查看該線程主要在進行的工做。這裏又分爲兩種狀況
  • 若是是正常的用戶線程，則經過該線程的堆棧信息查看其具體是在哪處用戶代碼處運行比較消耗CPU；
  • 若是該線程是VM Thread，則經過jstat -gcutil <pid> <period> <times>命令監控當前系統的GC情況，而後經過jmap dump:format=b,file=<filepath> <pid>導出系統當前的內存數據。導出以後將內存狀況放到eclipse的mat工具中進行分析便可得出內存中主要是什麼對象比較消耗內存，進而能夠處理相關代碼；
• 若是經過top命令看到CPU並不高，而且系統內存佔用率也比較低。此時就能夠考慮是不是因爲另外三種狀況致使的問題。具體的能夠根據具體狀況分析：
  • 若是是接口調用比較耗時，而且是不定時出現，則能夠經過壓測的方式加大阻塞點出現的頻率，從而經過jstack查看堆棧信息，找到阻塞點；
  • 若是是某個功能忽然出現停滯的情況，這種狀況也沒法復現，此時能夠經過屢次導出jstack日誌的方式對比哪些用戶線程是一直都處於等待狀態，這些線程就是可能存在問題的線程；
  • 若是經過jstack能夠查看到死鎖狀態，則能夠檢查產生死鎖的兩個線程的具體阻塞點，從而處理相應的問題。

       本文主要是提出了五種常見的致使線上功能緩慢的問題，以及排查思路。固然，線上的問題出現的形式是多種多樣的，也不必定侷限於這幾種狀況，若是咱們可以仔細分析這些問題出現的場景，就能夠根據具體狀況具體分析，從而解決相應的問題。