Java應用故障排查（CPU占用高、內存占用高、Full GC頻繁等）

下面通過模擬實例分析排查Java應用程序CPU和內存占用過高的過程。如果是Java面試，這2個問題在面試過程中出現的概率很高，所以我打算在這里好好總結一下。

1、Java CPU過高的問題排查

舉個例子，如下： 

package com.classloading;
public class Test {
	static class MyThread extends Thread {
		public void run() { // 死循環，消耗CPU
			int i = 0;
			while (true) {
				i++;
			}
		}
	}
	public static void main(String args[]) throws InterruptedException {
		new MyThread().start();
		Thread.sleep(10000000);
	}
}

使用top命令查看占用CPU過高的進程。如下圖所示。

  

查看進程6102下線程的占用情況，如下圖所示。

 

使用如下命令將6122轉換為16進制表示，如下：

 

導出CPU占用高進程的線程棧。命令如下：

jstack pid >> java.txt 

內容如下：　　

mazhi@mazhi:~$ cat java.txt 
Attaching to remote server pid, please wait...
2021-02-23 15:38:18
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.192-b12 mixed mode):

"Attach Listener" #10 daemon prio=9 os_prio=0 tid=0x00007f4ee0001000 nid=0x1956 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
// 這是0x17ea線程，也是占用CPU最高的線程
"Thread-0" #9 prio=5 os_prio=0 tid=0x00007f4f180d6000 nid=0x17ea runnable [0x00007f4f044da000]
   java.lang.Thread.State: RUNNABLE
	at com.cpuhigh.Test$MyThread.run(Test.java:8)  // 這里指示第8行，則正是死循環的代碼開始

...

導出的堆棧信息有線程的狀態（一般要找RUNNABLE狀態）和調用堆棧結合來查找問題。線程dump分析：線程dump分析主要目的是定位線程長時間停頓的原因 

jstack是一個瞬時堆棧只記錄瞬時狀態

實際排查問題的時候jstack建議打印5次至少3次，根據多次的堆棧內容，再結合相關代碼段進行分析，定位高cpu出現的原因，高cpu可能是代碼段中某個bug導致的而不是堆棧打印出來的那幾行導致的。

 

cpu高的情況還有一種可能的原因，假如一個4核cpu的服務器我們看到總的cpu達到了100%+，按1之后觀察每個cpu的us(用戶空間占用cpu的百分比)，只有一個達到了90%+，其他都在1%左右（下圖只是演示top按1之后的效果並非真實場景）：

 

這種情況下可以重點考慮是不是頻繁Full GC引起的。因為我們知道Full GC的時候會有Stop The World這個動作，多核cpu的服務器，除了GC線程外，在Stop The World的時候都是會掛起的，直到Stop The World結束。以幾種老年代垃圾收集器為例：

• Serial Old收集器，全程Stop The World
• Parallel Old收集器，全程Stop The World
• CMS收集器，它在初始標記與並發標記兩個過程中，為了准確標記出需要回收的對象，都會Stop The World，但是相比前兩種大大減少了系統停頓時間

無論如何，當真正發生Stop The World的時候，就會出現GC線程在占用cpu工作而其他線程掛起的情況，自然表現也就為某個cpu的us很高而且他cpu的us很低。 

2、Java 內存過高的問題排查 

堆dump分析：堆dump分析主要目的是定位OOM異常的原因；解決oom問題四 部曲：
1.分析OOM異常的原因，堆溢出？棧溢出？本地內存溢出？

2.如果是堆溢出，導出堆dump，並對堆內存使用有個整體了解；

3.找到最有可能導致內存泄露的元凶，通常也就是消耗內存最多的對象；

4.使用輔助工具對dump文件進行分析；

注意其他幾類造成OOM異常的原因

1.Direct Memory
2.線程堆棧：單線程：StackOverflowError 多線程：OutOfMemoryError：unable to create new native thread
3.Socket 緩沖區：IOException：Too many open files

舉個例子如下：

package com.classloading;

import java.util.ArrayList;
import java.util.List;

public class Test {
	private static final int UNIT_MB = 1024 * 1024;
	
	public static void main(String args[]) throws InterruptedException{
		List<Object> x = new ArrayList<Object>();
		int i = 0;
		while(i<1000){
			x.add(new byte[UNIT_MB]);
			i++;
		}
		Thread.sleep(1000000000);
	}
}

通過jmap dump內存快照。如果是線上環境，注意dump之前必須先將流量切走，否則大內存dump是直接卡死服務。

命令行輸入：

jmap -histo <pid> | head -20

就可以查看某個pid的java服務占用內存排名前20的類，如下圖所示。

 

可以看到，占用內存最多的是byte字節數組，共有1008個實例。

jmap還有一個指令可以把整個內存情況轉成文件形式保存下來，如下：

jmap -dump:format=b,file=filename.bin <pid>

執行命令如下圖所示。

 

可以在JVM啟動時設置，如果發生OOM，則dump出文件。命令如下：

-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/heapdump.hprof

如果快照文件不大，可以下載到本地，然后通過MAT分析，也可以在線分析（https://fastthread.io/）；如果快照文件很大，可以在服務器上直接分析，使用的命令是：

jhat dump.hprof

jhat也是jdk內置的工具之一。主要是用來分析java堆的命令，可以將堆中的對象以html的形式顯示出來，包括對象的數量，大小等等，並支持對象查詢語言。命令執行后如下圖所示。

 

訪問如下圖所示。

其中的Show heap histogram就會顯示對象占用內在的大小。如下圖所示。 

 

使用MAT時，有時候這個工具還會提示某個對象異常。我們可以在Histogram 頁面，可以查看到對象數量排序，我們可以看到 Byte[] 數組排在了第一位，選中對象后右擊選擇 with incomming reference 功能，可以查看到具體哪個對象引用了這個對象。

3、JVM的Error日志

致命錯誤日志文件位置可以通過 -XX:ErrorFile進行指定，相關的信息如下：

這個文件主要包含如下內容：

• 日志頭文件
• 導致 crash 的線程信息
• 所有線程信息
• 安全點和鎖信息
• 堆信息
• 本地代碼緩存
• 編譯事件
• gc 相關記錄
• jvm 內存映射
• jvm 啟動參數
• 服務器信息

這對於一般的開發人員來說不太容易讀懂。在日志頭文件中有常見的描述是“EXCEPTION_STACK_OVERFLOW”，該描述表示這是個棧溢出導致的錯誤，這往往是應用程序中存在深層遞歸導致的

4、Full GC的排查

如果FullGC只是發生在老年代區，比較有經驗的開發人員還是容易發現問題的，一般都是一些代碼bug引起的。MetaSpace發生的FullGC經常會是一些詭異、隱晦的問題，很多和引入的第三方框架使用不當有關或者就是第三方框架有bug導致的，排查起來就很費時間。

YGC如果頻繁，會讓對象過早進入老年代，如果回收時間過長，會造成系統停頓時間長，造成服務超時等問題。系統中有許多方法可以觀察到Full GC，通常有3種方法，如下：

1、在系統中增加參數，記錄相關信息，如下：

-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:/home/mazhi/workspace/projectjava/projectjava01/gclog/gc.log

某一次記錄的日志信息如下：

Java HotSpot(TM) 64-Bit Server VM (25.192-b12) for linux-amd64 JRE (1.8.0_192-b12), built on Oct  6 2018 06:46:09 by "java_re" with gcc 7.3.0
Memory: 4k page, physical 8064700k(2091464k free), swap 8276988k(8276988k free)
CommandLine flags: -XX:InitialHeapSize=129035200 -XX:MaxHeapSize=2064563200 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
0.073: [GC (System.gc()) [PSYoungGen: 634K->320K(36864K)] 634K->320K(121856K), 0.0015284 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
0.075: [Full GC (System.gc()) [PSYoungGen: 320K->0K(36864K)] [ParOldGen: 0K->258K(84992K)] 320K->258K(121856K), [Metaspace: 2473K->2473K(1056768K)], 0.0035519 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
Heap
 PSYoungGen      total 36864K, used 1270K [0x00000000d6f80000, 0x00000000d9880000, 0x0000000100000000)
  eden space 31744K, 4% used [0x00000000d6f80000,0x00000000d70bd890,0x00000000d8e80000)
  from space 5120K, 0% used [0x00000000d8e80000,0x00000000d8e80000,0x00000000d9380000)
  to   space 5120K, 0% used [0x00000000d9380000,0x00000000d9380000,0x00000000d9880000)
 ParOldGen       total 84992K, used 258K [0x0000000084e00000, 0x000000008a100000, 0x00000000d6f80000)
  object space 84992K, 0% used [0x0000000084e00000,0x0000000084e40b30,0x000000008a100000)
 Metaspace       used 2479K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 265K, capacity 386K, committed 512K, reserved 1048576K

給出的信息還是比較全面詳細的，包括堆和元空間GC前與GC后的變化，當前虛擬機使用的命令等。

2、通過監控查看，如Pinpoint APM監控工具等

3、通過Linux命令查看，如：

jstat -gc 4383 5000

即會每5秒一次顯示進程號為4383的java進程的GC情況， -XX:+PrintGCDetails 用來打印詳細的GC信息。如某次的詳細信息如下圖所示。

當發現是Full GC頻繁時，首先要知道，哪些情況下會觸發Full GC，原因如下：

1. 程序執行了System.gc();
2. 執行了jmap命令；
3. 大對象直接進入了老年代導致老年代內存不足，達到了GC閾值；
4. 程序中存在內存泄露，導致老年代內存緩慢增長，且無法被回收，達到了GC閾值；
5. 老年代存在內存碎片，導致新晉升的對象空間不足，觸發GC。

對於第1個原因，如果老年代還有大量空閑空間時就觸發，則有可能是調用了System.gc()。對於后面3個原因，通常需要觀察Full GC之前與之后堆的內存變化來確定。可以通過GC日志或jvisualvm等圖形化工具來查看，如果Full GC前與后堆回不到原來的大小並且堆大小一直增大，則可能是內存泄露，否則可能就是對象過於頻繁進入老年代了，需要找出這些對象。可以通過jmap命令來dump出文件。我們可以在線上開啟了 -XX:+HeapDumpBeforeFullGC。使用jvisualvm查看哪些對象占用的比較大的內存（能給出實例占用的大小和占用內存的百分比）

常用到的一些命令及圖形化工具如下圖所示。

5、應用故障你怎么樣排除問題？

應用故障一般指應用運行緩慢、用戶體驗差或者周期性的出現卡頓,排除的思路：
1.檢查應用所在的生產環境的軟硬件以及網絡環境，排除外圍因素；
2.確定是否為OOM異常，這類異常影響最惡劣，但是比較容易排查；
3.確定是否有大量長時間停頓的應用線程，非常占用cpu資源；
4.周期性的卡頓很可能是垃圾回收造成，web后端系統建議使用cms垃圾回收器

6、什么情況下會發生棧內存溢出？

如果線程請求的棧深度大於虛擬機所允許的深度，將拋出StackOverflowError異常。 如果虛擬機在動態擴展棧時無法申請到足夠的內存空間，則拋出OutOfMemoryError異常。 

7、頻繁minor gc怎么辦？可能造成的原因是什么？如何避免？minor gc運行的很慢有可能是什么原因引起的？ 

如下2個原因可能導致minor gc頻繁：

1、 產生了太多朝生夕滅的對象導致需要頻繁minor gc

2、 新生代空間設置的比較小

可以適當擴大新生代空間的大小，或者G1會根據實際的GC情況(主要是暫停時間)來動態的調整新生代的大小,主要是Eden Region的個數。

一個案例是，Object轉xml，xml轉Object，代碼中每處都new XStream()去進行xml序列化與反序列化，回收速度跟不上new的速度，YoungGC次數陡增。

minor gc運行的很慢有可能是什么原因引起的？

1、新生代空間設置過大。

2、對象引用鏈較長，或者存活小對象的數量太多，進行可達性分析時間較長。

3、新生代survivor區設置的比較小，清理后剩余的對象不能裝進去需要移動到老年代，造成移動開銷。

4、內存分配擔保失敗，由minor gc轉化為full gc

5、采用的垃圾收集器效率較低，比如新生代使用serial收集器

8、load飆升怎么處理？什么情況可能會遇到上述情況？ 

可參考：https://www.cnblogs.com/xrq730/p/11041741.html 

對於load的理解如下：

一個單核的處理器可以形象得比喻成一條單車道，車輛依次行駛在這條單車道上，前車駛過之后后車才可以行駛。
如果前面沒有車輛，那么你順利通過；如果車輛眾多，那么你需要等待前車通過之后才可以通過。 因此，需要些特定的代號表示目前的車流情況，例如： 

1. 等於0.00，表示目前橋面上沒有任何的車流。實際上這種情況0.00和1.00之間是相同的，總而言之很通暢，過往的車輛可以絲毫不用等待的通過
2. 等於1.00，表示剛好是在這座橋的承受范圍內。這種情況不算糟糕，只是車流會有些堵，不過這種情況可能會造成交通越來越慢 
3. 大於1.00，那么說明這座橋已經超出負荷，交通嚴重的擁堵。那么情況有多糟糕? 例如2.00的情況說明車流已經超出了橋所能承受的一倍，那么將有多余過橋一倍的車輛正在焦急的等待  

系統load是處於運行狀態或者不可中斷狀態的進程的平均數（標紅部分表示被算入load的內容）。一個處於運行狀態的進程表示正在使用cpu或者等待使用cpu，一個不可中斷狀態的進程表示正在等待IO，例如磁盤IO。load的平均值通過3個時間間隔來展示，就是我們看到的1分鍾、5分鍾、15分鍾，load值和cpu核數有關，單核cpu的load=1表示系統一直處在負載狀態，但是4核cpu的load=1表示系統有75%的空閑。

特別注意，load指的是所有核的平均值，這和cpu的值是有區別的。

還有一個重要的點是，查了資料發現，雖然上面一直強調的是"進程"，但是進程中的線程數也是會被當作不同的進程來計算的，假如一個進程產生1000個線程同時運行，那運行隊列的長度就是1000，load average就是1000。

load是以線程/進程作為統計指標，無論請求數是多少，最終都需要線程去處理，而工作線程的處理性能直接決定了最終的load值  

load高、cpu高的問題排查思路 

首先拋出一個觀點：cpu高不是問題，由cpu高引起的load高才是問題，load是判斷系統能力指標的依據。 

前面說了這么多，這里總結一下load高常見的、可能的一些原因： 

• 死循環或者不合理的大量循環操作，如果不是循環操作，按照現代cpu的處理速度來說處理一大段代碼也就一會會兒的事，基本對能力無消耗
• 頻繁的YoungGC
• 頻繁的FullGC
• 高磁盤IO
• 高網絡IO 

線上遇到問題的時候首先不要慌，因為大部分load高的問題都集中在以上幾個點里面，以下分析問題的步驟或許能幫你整理思路： 

• top先查看用戶us與空閑us（id）的cpu占比，目的是確認load高是否高cpu起的
• 如果是高cpu引起的，那么確認一下是否gc引起的，jstat命令 + gc日志基本就能確認
• gc引起的高cpu直接dump，非gc引起的分析線程堆棧
• 如果不是高cpu引起的，查看磁盤io占比（wa：cpu等待磁盤寫入完成時間，如果一台機器看到wa特別高，那么一般說明是磁盤IO出現問題，可以使用iostat等命令繼續進行詳細分析
  ），如果是，那么打線程堆棧分析是否有大量的文件io
• 如果不是高cpu引起的，且不是磁盤io導致的，檢查各依賴子系統的調用耗時，高耗時的網絡調用很可能是罪魁禍首 

最后還是不行，當束手無策時，jstack打印堆棧多分析分析吧，或許能靈光一現能找到錯誤原因。

9、問題排查之服務響應超時　　

（1）JVM頻繁做垃圾回收，或STW時間過長

（2）線程池中的線程執行任務太慢，可能導致阻塞，這樣其它任務就壓入隊列中了 

搶購活動出現了大量超時報警，不過比我預料的要好一點，起碼沒有掛掉重啟。

通過工具分析，我發現 cs（上下文切換每秒次數）指標已經接近了 60w ，平時的話最高 5w。再通過日志分析，我發現了大量帶有 wait() 的 Exception，由此初步懷疑是大量線程處理不及時導致的，進一步鎖定問題是連接池大小設置不合理。后來我就模擬了生產環境配置，對連接數壓測進行調節，降低最大線程數，最后系統的性能就上去了。