JVM 性能調優實戰指南
在當今軟件開發領域,Java 虛擬機(JVM)作為運行 Java 應用程序的核心組件,其性能優化顯得尤為重要。無論是大型企業應用還是微服務架構,高效的 JVM 調優都能顯著提升系統的響應速度、吞吐量以及穩定性。本文將從理論到實踐,全面解析 JVM 的工作原理及其關鍵配置參數,并通過實際案例分享如何進行有效的性能調優。無論您是初學者還是有經驗的開發者,相信本文都能為您帶來新的啟發與收獲。
一、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 5
2.拆解與分析JVM的GC日志
為了演示如何查看GC日志,筆者給出下面這樣一段代碼并結合JVM參數配置(后文會給到)展示JVM如何進行垃圾回收,注意筆者這里新生代的垃圾回收算法是ParNew而老年代用到的是CMS:
public static void main(String[] args) {
//分配1M內存空間
byte[] bytes = new byte[1024 * 1024];
//觸發minor gc,剩余512k,然后將1M空間存放至新生代,堆空間大約剩下1.5M
bytes = new byte[1024 * 1024];
//分配至新生代約2.5M
bytes = new byte[1024 * 1024];
//新生代空間不足,觸發full gc,新生代空間全回收,并執行CMS GC,完成后將對象存放至新生代
byte[] byte2 = new byte[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 -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的數組存放至新生代,此時新生代的堆空間大約是1M:
然后第三行再次分配數組,新生代空間充裕,直接存入:
最后一次分配2M數組時,新生代空間不足且空間分配擔保失敗,直接觸發FULL GC,從日志中我們可以看到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]
最后就是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重新并發掃描進入到老年代的對象,最后時CMS-concurrent-abortable-preclean該階段并發運行至eden區空間占用率達到滿意:
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 和major 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 = new byte[1024 * 1024];
bytes = new byte[1024 * 1024];
bytes = new byte[1024 * 1024];
//創建2M的新對象觸發GC
byte[] byte2 = new byte[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.將年輕代空間調大,是否會更加耗時?
答案是不會的,原因有以下兩點:
- JVM操作本質上都是內存操作,相對而言不會太慢。
- 我們將一次GC的時間拆分為t1和t2,t1是掃描年輕代空間是否有垃圾的時間,這個時間的幾乎可以忽略不計。而t2則是將eden空間存活的對象復制到survivor區的時間,這個復制操作則是t1時間的10倍。
由此可以看出,避免耗時的正確做法是合理評估新生代堆空間,減少非必要的復制操作,所以說調整新生代的空間并不會導致進一步的耗時問題。
五、頻繁的FULL GC
1.復現問題
我們現在模擬一個場景,我們的應用中有一個定時任務,這個定時任務每隔1s會想另一個定時任務線程池中提交100個任務,每個任務都會針對Obj 對象進行方法調用:
@Component
public class Task {
private static Logger logger = LoggerFactory.getLogger(Task.class);
private static final ScheduledThreadPoolExecutor executor =
new ScheduledThreadPoolExecutor(50,
new ThreadPoolExecutor.DiscardOldestPolicy());
private static class Obj {
private String name = "name";
private int 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.0 640.0 0.0 640.0 5504.0 665.5 13696.0 11176.2 31488.0 28992.6 4352.0 3889.5 39 0.084 15 0.100 0.184
640.0 640.0 0.0 640.0 5504.0 1487.2 13696.0 11176.2 31488.0 28992.6 4352.0 3889.5 39 0.084 25 0.142 0.227
640.0 640.0 0.0 640.0 5504.0 1697.8 13696.0 11176.2 31488.0 28992.6 4352.0 3889.5 39 0.084 35 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():這種情況需要修改代碼即可,我們不該頻繁調用這個方法的。
- 老年區空間過小:視情況適當擴大空間。
- 大對象過多:這種情況視情況決定是擴大老年代空間或者將大對象拆分。
一般來說,我們優先考慮調整堆內存空間,其次才是針對業務邏輯的代碼處理進行更進一步的優化。