JVM 內存溢出排查指南
作者：碼農SharkChili
本文通過幾個比較經典的示例演示了JVM進行垃圾回收的過程以及如何進行JVM內存調優，希望對你有幫助。
本文針對常見的幾種GC情況結合日志進行分析介紹，希望對你有幫助。
一、JVM常見命令介紹
篇幅原因關于JVM常見指令的使用與介紹，需要了解的讀者可以移步參考筆者寫的這篇文章：《JVM 指令集概覽：基礎與應用》
二、詳解JVM的GC
1. 定位GC情況的兩種方式
獲取GC日志方式大抵有兩種，第一種就是設定JVM參數在程序啟動時查看，具體的命令參數為:
-XX:+PrintGCDetails # 打印GC日志
-XX:+PrintGCTimeStamps # 打印每一次觸發GC時發生的時間第二種則是在服務器上監控:使用jstat查看,如下所示，命令格式為jstat -gc pid 輸出間隔時長 輸出次數，例如筆者希望每隔1秒輸出1次，并且打印5次，對應的指令如下：
jstat -gc 21608 1000 52. 拆解與分析JVM的GC日志
為了演示如何查看GC日志，筆者給出下面這樣一段代碼并結合JVM參數配置(后文會給到)展示JVM如何進行垃圾回收：
public static void main(String[] args) {
//分配1M內存空間
byte[] bytes = newbyte[1024 * 1024];
//觸發minor gc，剩余512k，然后將1M空間存放至新生代，堆空間大約剩下1.5M
bytes = newbyte[1024 * 1024];
//分配至新生代約2.5M
bytes = newbyte[1024 * 1024];
//新生代空間不足，觸發full gc，新生代空間全回收，并執行CMS GC，完成后將對象存放至新生代
byte[] byte2 = newbyte[2 * 1024 * 1024];
}對應我們也給出如下JVM配置參數指明新生代、老年代堆空間大小為5M，并指明新生代Eden和survivor區的比例為8:1:1，同時我們也指定的新生代和老年代垃圾回收算法分別是ParNewGC和CMS：
-XX:NewSize=5M -XX:MaxNewSize=5M -XX:InitialHeapSize=10M -XX:MaxHeapSize=10M -XX:SurvivorRatio=8 -XX:PretenureSizeThreshold=10M -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps詳細解釋的含義如下，讀者可自行參閱：
-XX:NewSize=5M：設置新生代的初始大小為 5MB。
-XX:MaxNewSize=5M：設置新生代的最大大小為 5MB。
-XX:InitialHeapSize=10M：設置 JVM 堆的初始大小為 10MB。
-XX:MaxHeapSize=10M：設置 JVM 堆的最大大小為 10MB。
-XX:SurvivorRatio=8：設置 Eden 區與 Survivor 區的比例為 8，即 Eden 占用 8/10 的新生代空間，兩個 Survivor 各占 1/10。
-XX:PretenureSizeThreshold=10M：設置對象直接進入老年代的閾值為 10MB，超過這個大小的對象會直接分配到老年代。
-XX:+UseParNewGC：啟用并行新生成收集器（Parallel New Generation Collector），用于多線程環境下的新生代垃圾回收。
-XX:+UseConcMarkSweepGC：啟用并發標記清除收集器（Concurrent Mark Sweep Collector），用于多線程環境下的老年代垃圾回收。
-XX:+PrintGCDetails：打印詳細的垃圾回收日志信息。
-XX:+PrintGCTimeStamps：在垃圾回收日志中添加時間戳。此時我們就以逐行執行的方式講解GC過程：
- 首先代碼執行到byte[] bytes = new byte[1024 * 1024];，此時新生代空間充裕，沒有任何輸出。
- 執行第二行代碼bytes = new byte[1024 * 1024];再次進程內存分配時，發現新生代空間不足出現以此minor gc
對應輸出結果如下，我們大體可以看出GC原因是Allocation Failure即新生代不能分配對象，觸發一次新生代GC，新生代GC前后空間由3348K變為512K，整堆空間由3348K變為1692K，最后輸出了GC耗時、系統響應耗時以及應用程序暫停時間：
2.938: [GC (Allocation Failure) 2.938: [ParNew: 3348K->512K(4608K), 0.0016244 secs] 3348K->1692K(9728K), 0.0016904 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]完成上述GC，將1M的數組存放至新生代，此時新生代的堆空間大約是1.5M：
然后第三行再次分配數組，新生代空間充裕，直接存入：
最后一次分配2M數組時，從日志中我們可以看到minor gc直接將上述的所有字節數組都回收了:
9.689: [GC (Allocation Failure) 9.689: [ParNew: 2626K->0K(4608K), 0.0021520 secs] 3806K->2746K(9728K), 0.0021903 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]在新生代空間不足嘗試到老年代分配對象時，因為堆空間且空間分配擔保失敗，不夠直接觸發FULL GC。從日志中可以看到CMS老年代GC，首先進行初始標記階段該階段為STW并找到所有的GC root，從日志中我們看到：
- 老年代使用的容量為2718K且總容量為5120K
- 當前堆的實際大小和總容量為4766K(9728K)標記：
2.057: [GC (CMS Initial Mark) [1 CMS-initial-mark: 2718K(5120K)] 4766K(9728K), 0.0005690 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]然后進入并發標記階段該階段不會STW，執行如下步驟：
- CMS-concurrent-mark標記 gc root可達的老年代對象
- CMS-concurrent-preclean該階段會處理那些dirty card中標記的對象，dirty card即臟卡，本質上那個就是處理那些并發標記階段引用關系發生變化的區域，通過在這個階段盡可能的標記可以減少最終標記即remark階段的耗時
- CMS-concurrent-abortable-preclean即并發可終止的預清理階段，繼續執行步驟2的任務，同樣是為了減小remark階段的工作量，默認情況下CMS要求這一步必須完成Eden剩余50%或耗時超過5s才能進入下一個階段：
2.058: [CMS-concurrent-mark-start]
2.059: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2.059: [CMS-concurrent-preclean-start]
2.059: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2.059: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 7.163: [CMS-concurrent-abortable-preclean: 0.005/5.105 secs] [Times: user=0.00 sys=0.00, real=5.10 secs]最后就到了最終標記階段，該階段會STW，從日志輸出可以看出新生代占用2048k，當前這個重新標記階段Rescan 花費了0.0004620 secs，其余就是處理弱引用、卸載無用的類以及清理元數據等花費時間和耗時：
7.164: [GC (CMS Final Remark) [YG occupancy: 2048 K (4608 K)]7.164: [Rescan (parallel) , 0.0004620 secs]7.164: [weak refs processing, 0.0001727 secs]7.164: [class unloading, 0.0005772 secs]7.165: [scrub symbol table, 0.0011975 secs]7.166: [scrub string table, 0.0003404 secs][1 CMS-remark: 2718K(5120K)] 4766K(9728K), 0.0030256 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]最后就是并發的清理垃圾會重置標記，等待下一個周期的GC：
7.167: [CMS-concurrent-sweep-start]
7.168: [CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
7.168: [CMS-concurrent-reset-start]
7.168: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]最后我們查看內存使用情況可以看到，新生代的2M就是我們最后分配的數組，在eden區，而老年代使用了1677K：
Heap
par new generation total 4608K, used 2089K [0x00000000ff600000, 0x00000000ffb00000, 0x00000000ffb00000)
eden space 4096K, 51% used [0x00000000ff600000, 0x00000000ff80a558, 0x00000000ffa00000)
from space 512K, 0% used [0x00000000ffa00000, 0x00000000ffa00000, 0x00000000ffa80000)
to space 512K, 0% used [0x00000000ffa80000, 0x00000000ffa80000, 0x00000000ffb00000)
concurrent mark-sweep generation total 5120K, used 1677K [0x00000000ffb00000, 0x0000000100000000, 0x0000000100000000)
Metaspace used 3124K, capacity 4486K, committed 4864K, reserved 1056768K
class space used 327K, capacity 386K, committed 512K, reserved 1048576K三、了解JVM幾種GC的區別
- Minor GC:發生在年輕代的空間回收，包含eden和survivor，也叫做Young GC。
- Major GC:在老年代堆區進行空間回收。
- Full GC:清理所有堆區的內存空間的垃圾內存，包括年輕代和老年代。
四、頻繁的minor gc問題與解決思路
1. 問題復現
我們嘗試編寫一個程序，設置該程序的堆內存新生代為5M，按照8:1:1的比例分配，這也就意為著Eden區內存大小為4M，然后S區分別是512K，這也就意味著在待分配對象加Eden區堆空間超過4M就會觸發minor gc：
基于上述說法，我們給出下面這段代碼：
public static void main(String[] args) throws Exception {
while (true) {
//分配3M數組
byte[] bytes = newbyte[1024 * 1024];
bytes = newbyte[1024 * 1024];
bytes = newbyte[1024 * 1024];
//創建2M的新對象觸發GC
byte[] byte2 = newbyte[2 * 1024 * 1024];
Thread.sleep(1000);
}
}為了演示年輕代的回收行為，我們需要在對這個應用程序的年輕代堆內存改為5M，且Eden區和S區的比例為8:1:1，同時也打印GC日志信息：
-XX:NewSize=5M -XX:MaxNewSize=5M -XX:InitialHeapSize=10M -XX:MaxHeapSize=10M -XX:SurvivorRatio=8 -XX:PretenureSizeThreshold=10M -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps輸出結果如下，GC日志顯示每秒基本都會觸發一次Minor GC，進而間接導致頻繁的major gc:
2. 問題拆解與修復
結合我們的配置可知，我們頻繁分配對象導致新生代進行頻繁的GC，又因為S區大小無法容納存活的對象，進而使得這些對象提前進入老年代，導致major GC也隨之頻繁，所以解決的辦法也比較簡單，按照等比例調整大堆空間，即將新生代堆空間調整至10M，保證S區各有2M空間以容納新生代存活的對象：
-XX:NewSize=10M -XX:MaxNewSize=10M -XX:InitialHeapSize=100M -XX:MaxHeapSize=100M -XX:SurvivorRatio=8 -XX:PretenureSizeThreshold=10M -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps可以看到經過調整之后，基本上Minor gc就能解決問題：
3. 將年輕代空間調大，是否會更加耗時？
答案是不會的，原因有以下2點：
- JVM操作本質上都是內存操作，相對而言不會太慢。
- 我們將一次GC的時間拆分為t1和t2，t1是掃描年輕代空間是否有垃圾的時間，這個時間的幾乎可以忽略不計。而t2則是將eden空間存活的對象復制到survivor區的時間，這個復制操作則是t1時間的10倍。
由此可以看出，避免耗時的正確做法是合理評估新生代堆空間，減少非必要的復制操作，所以說調整新生代的空間并不會導致進一步的耗時問題。
五、頻繁的FULL GC
1. 復現問題
我們現在模擬一個場景，我們的應用中有一個定時任務，這個定時任務每隔1s會想另一個定時任務線程池中提交100個任務，每個任務都會針對Obj 對象進行方法調用：
@Component
publicclass Task {
privatestatic Logger logger = LoggerFactory.getLogger(Task.class);
privatestaticfinal ScheduledThreadPoolExecutor executor =
new ScheduledThreadPoolExecutor(50,
new ThreadPoolExecutor.DiscardOldestPolicy());
privatestaticclass Obj {
private String name = "name";
privateint age = 18;
private String gender = "man";
private LocalDate birthday = LocalDate.MAX;
public void func() {
//這個方法什么也不做
}
//返回count個Obj對象
private static List<Obj> getObjList(int count) {
List<Obj> objList = new ArrayList<>(count);
for (int i = 0; i != count; ++i) {
objList.add(new Obj());
}
return objList;
}
}
@Scheduled(cron = "0/1 * * * * ? ") //每1秒執行一次
public void execute() {
logger.info("1s一次定時任務");
//向線程池提交100個任務
Obj.getObjList(100).forEach(i -> executor.scheduleWithFixedDelay(
i::func, 2, 3, TimeUnit.SECONDS
));
}
}完成后我們設置下面這段JVM參數后，將其啟動：
-Xms20M -Xmx20M -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps不久后，控制臺出現頻繁的full gc，如果在生產環境，頻繁的full gc導致stw會導致系統吞吐量下降：
.......
1288.133: [Full GC (Allocation Failure) 1288.133: [CMS1288.142: [CMS-concurrent-preclean: 0.012/0.012 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
(concurrent mode failure): 13695K->13695K(13696K), 0.0610050 secs] 19839K->19836K(19840K), [Metaspace: 29026K->29026K(1077248K)], 0.0610521 secs] [Times: user=0.06 sys=0.00, real=0.06 secs]
1288.258: [Full GC (Allocation Failure) 1288.258: [CMS: 13695K->13695K(13696K), 0.0612134 secs] 19839K->19836K(19840K), [Metaspace: 29026K->29026K(1077248K)], 0.0612676 secs] [Times: user=0.06 sys=0.00, real=0.06 secs]
1288.320: [GC (CMS Initial Mark) [1 CMS-initial-mark: 13695K(13696K)] 19836K(19840K), 0.0041303 secs] [Times: user=0.03 sys=0.00, real=0.00 secs]
......2. 排查思路
我們定位到程序號后，使用jstat -gc pid10000 10觀察其gc情況，可以看到每隔10s，就會增加大量的full gc：
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
640.0640.0 0.0 640.0 5504.0 665.5 13696.0 11176.2 31488.028992.64352.03889.5 39 0.08415 0.100 0.184
640.0640.0 0.0 640.0 5504.0 1487.2 13696.0 11176.2 31488.028992.64352.03889.5 39 0.08425 0.142 0.227
640.0640.0 0.0 640.0 5504.0 1697.8 13696.0 11176.2 31488.028992.64352.03889.5 39 0.08435 0.185 0.269
......再查看jmap -heap pid查看堆區使用情況，可以看到老年代的使用率還是蠻高的：
Attaching to process ID 26176, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.212-b10
using parallel threads in the new generation.
using thread-local object allocation.
Concurrent Mark-Sweep GC
Heap Configuration:
MinHeapFreeRatio = 40
MaxHeapFreeRatio = 70
MaxHeapSize = 20971520 (20.0MB)
NewSize = 6946816 (6.625MB)
MaxNewSize = 6946816 (6.625MB)
OldSize = 14024704 (13.375MB)
NewRatio = 2
SurvivorRatio = 8
MetaspaceSize = 21807104 (20.796875MB)
CompressedClassSpaceSize = 1073741824 (1024.0MB)
MaxMetaspaceSize = 17592186044415 MB
G1HeapRegionSize = 0 (0.0MB)
Heap Usage:
New Generation (Eden + 1 Survivor Space):
capacity = 6291456 (6.0MB)
used = 5088288 (4.852569580078125MB)
free = 1203168 (1.147430419921875MB)
80.87615966796875% used
Eden Space:
capacity = 5636096 (5.375MB)
used = 5088288 (4.852569580078125MB)
free = 547808 (0.522430419921875MB)
90.28036428052326% used
From Space:
capacity = 655360 (0.625MB)
used = 0 (0.0MB)
free = 655360 (0.625MB)
0.0% used
To Space:
capacity = 655360 (0.625MB)
used = 0 (0.0MB)
free = 655360 (0.625MB)
0.0% used
concurrent mark-sweep generation:
capacity = 14024704 (13.375MB)
used = 13819664 (13.179458618164062MB)
free = 205040 (0.1955413818359375MB)
98.53800836010514% used
12064 interned Strings occupying 1120288 bytes.在排除內存泄漏的問題后，我們通過jmap定位進程中導致是什么對象導致老年代堆區被大量占用：
jmap -histo 7476 | head -n 20可以看到前20名中的對象都是和定時任務相關，有一個Task$Obj對象非常搶眼，很明顯就是因為它的數量過多導致的，此時我們就可以通過定位代碼確定如何解決，常見方案無非是: 優化代碼、增加空間兩種方式，一般來說我們都會采用代碼優化的方式去解決。
$
num #instances #bytes class name
----------------------------------------------
1: 50760 3654720 java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask
2: 30799 2901552 [C
3: 88986 2847552 java.util.concurrent.locks.AbstractQueuedSynchronizer$Node
4: 50700 1622400 com.example.jstackTest.Task$Obj
5: 50760 1218240 java.util.concurrent.Executors$RunnableAdapter
6: 50700 811200 com.example.jstackTest.Task$$Lambda$587/1605553313
7: 6391 707928 java.lang.Class
8: 29256 702144 java.lang.String
9: 13577 434464 java.util.concurrent.ConcurrentHashMap$Node
10: 6363 341016 [Ljava.lang.Object;
11: 1722 312440 [B
12: 3414 230424 [I
13: 4 210680 [Ljava.util.concurrent.RunnableScheduledFuture;
14: 5223 208920 java.util.LinkedHashMap$Entry
15: 2297 202136 java.lang.reflect.Method
16: 2262 193760 [Ljava.util.HashMap$Node;
17: 5668 181376 java.util.HashMap$Node而本次問題也很明顯，任務是一個個提交到定時任務線程池中，是由于定時任務隊列DelayedWorkQueue不斷堆積任務導致內存被打滿。所以最終改成將一個批處理一次性提交到定時任務中立刻將這一批對象回收從而避免耗時任務堆積一堆對象：
@Scheduled(cron = "0/1 * * * * ? ") //每1秒執行一次
public void execute() {
logger.info("1s一次定時任務");
//向線程池提交100個任務
executor.scheduleWithFixedDelay(() -> {
Obj.getObjList(100).forEach(i -> i.func());
}, 2, 3, TimeUnit.SECONDS
);
}3. 頻繁FULL GC的原因和解決對策
總的來說原因可以頻繁FULL GC分為3個:
- 用戶頻繁調用System.gc()：這種情況需要修改代碼即可，我們不該頻繁調用這個方法的。
- 老年區空間過小：視情況適當擴大空間。
- 大對象過多：這種情況視情況決定是擴大老年代空間或者將大對象拆分。
一般來說，我們優先考慮調整堆內存空間，其次才是針對業務邏輯的代碼處理進行更進一步的優化。
責任編輯：趙寧寧
來源：
寫代碼的SharkChili
