JVM 性能調(diào)優(yōu)實(shí)戰(zhàn)指南
在當(dāng)今軟件開(kāi)發(fā)領(lǐng)域，Java 虛擬機(jī)（JVM）作為運(yùn)行 Java 應(yīng)用程序的核心組件，其性能優(yōu)化顯得尤為重要。無(wú)論是大型企業(yè)應(yīng)用還是微服務(wù)架構(gòu)，高效的 JVM 調(diào)優(yōu)都能顯著提升系統(tǒng)的響應(yīng)速度、吞吐量以及穩(wěn)定性。本文將從理論到實(shí)踐，全面解析 JVM 的工作原理及其關(guān)鍵配置參數(shù)，并通過(guò)實(shí)際案例分享如何進(jìn)行有效的性能調(diào)優(yōu)。無(wú)論您是初學(xué)者還是有經(jīng)驗(yàn)的開(kāi)發(fā)者，相信本文都能為您帶來(lái)新的啟發(fā)與收獲。
一、JVM常見(jiàn)命令介紹
篇幅原因關(guān)于JVM常見(jiàn)指令的使用與介紹，需要了解的讀者可以移步參考筆者寫(xiě)的這篇文章《JVM指令集概覽：基礎(chǔ)與應(yīng)用》
二、詳解JVM的GC
1.定位GC情況的兩種方式
獲取GC日志方式大抵有兩種，第一種就是設(shè)定JVM參數(shù)在程序啟動(dòng)時(shí)查看，具體的命令參數(shù)為:
-XX:+PrintGCDetails # 打印GC日志
-XX:+PrintGCTimeStamps # 打印每一次觸發(fā)GC時(shí)發(fā)生的時(shí)間第二種則是在服務(wù)器上監(jiān)控:使用jstat查看,如下所示，命令格式為jstat -gc pid 輸出間隔時(shí)長(zhǎng) 輸出次數(shù)，例如筆者希望每隔1秒輸出1次，并且打印5次，對(duì)應(yīng)的指令如下：
jstat -gc 21608 1000 52.拆解與分析JVM的GC日志
為了演示如何查看GC日志，筆者給出下面這樣一段代碼并結(jié)合JVM參數(shù)配置(后文會(huì)給到)展示JVM如何進(jìn)行垃圾回收，注意筆者這里新生代的垃圾回收算法是ParNew而老年代用到的是CMS：
public static void main(String[] args) {
//分配1M內(nèi)存空間
byte[] bytes = new byte[1024 * 1024];
//觸發(fā)minor gc，剩余512k，然后將1M空間存放至新生代，堆空間大約剩下1.5M
bytes = new byte[1024 * 1024];
//分配至新生代約2.5M
bytes = new byte[1024 * 1024];
//新生代空間不足，觸發(fā)full gc，新生代空間全回收，并執(zhí)行CMS GC，完成后將對(duì)象存放至新生代
byte[] byte2 = new byte[2 * 1024 * 1024];
}對(duì)應(yīng)我們也給出如下JVM配置參數(shù)指明新生代、老年代堆空間大小為5M，并指明新生代Eden和survivor區(qū)的比例為8:1:1，同時(shí)我們也指定的新生代和老年代垃圾回收算法分別是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對(duì)應(yīng)的含義如下，讀者可自行參閱：
-XX:NewSize=5M：設(shè)置新生代的初始大小為 5MB。
-XX:MaxNewSize=5M：設(shè)置新生代的最大大小為 5MB。
-XX:InitialHeapSize=10M：設(shè)置 JVM 堆的初始大小為 10MB。
-XX:MaxHeapSize=10M：設(shè)置 JVM 堆的最大大小為 10MB。
-XX:SurvivorRatio=8：設(shè)置 Eden 區(qū)與 Survivor 區(qū)的比例為 8，即 Eden 占用 8/10 的新生代空間，兩個(gè) Survivor 各占 1/10。
-XX:PretenureSizeThreshold=10M：設(shè)置對(duì)象直接進(jìn)入老年代的閾值為 10MB，超過(guò)這個(gè)大小的對(duì)象會(huì)直接分配到老年代。
-XX:+UseParNewGC：?jiǎn)⒂貌⑿行律墒占鳎≒arallel New Generation Collector），用于多線(xiàn)程環(huán)境下的新生代垃圾回收。
-XX:+UseConcMarkSweepGC：?jiǎn)⒂貌l(fā)標(biāo)記清除收集器（Concurrent Mark Sweep Collector），用于多線(xiàn)程環(huán)境下的老年代垃圾回收。
-XX:+PrintGCDetails：打印詳細(xì)的垃圾回收日志信息。
-XX:+PrintGCTimeStamps：在垃圾回收日志中添加時(shí)間戳。此時(shí)我們就以逐行執(zhí)行的方式講解GC過(guò)程，首先代碼執(zhí)行到byte[] bytes = new byte[1024 * 1024];，此時(shí)新生代空間充裕，沒(méi)有任何輸出。 執(zhí)行第二行代碼bytes = new byte[1024 * 1024];再次進(jìn)程內(nèi)存分配時(shí)，發(fā)現(xiàn)新生代空間不足出現(xiàn)以此minor gc，對(duì)應(yīng)輸出結(jié)果如下，我們大體可以看出GC原因是Allocation Failure即新生代不能分配對(duì)象，觸發(fā)一次新生代GC，新生代GC前后空間由3348K變?yōu)?12K，整堆空間由3348K變?yōu)?692K，最后輸出了GC耗時(shí)、系統(tǒng)響應(yīng)耗時(shí)以及應(yīng)用程序暫停時(shí)間：
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的數(shù)組存放至新生代，此時(shí)新生代的堆空間大約是1M：
然后第三行再次分配數(shù)組，新生代空間充裕，直接存入：
最后一次分配2M數(shù)組時(shí)，新生代空間不足且空間分配擔(dān)保失敗，直接觸發(fā)FULL GC，從日志中我們可以看到minor gc直接將上述的所有字節(jié)數(shù)組都回收了：
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，首先進(jìn)行初始標(biāo)記階段該階段為STW并找到所有的GC root，從日志中我們看到老年代使用的容量為2718K且總?cè)萘繛?120K，后面的4766K(9728K)標(biāo)記為當(dāng)前堆的實(shí)際大小和總?cè)萘浚?/p>
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] 然后進(jìn)入并發(fā)標(biāo)記階段該階段不會(huì)STW，先是CMS-concurrent-mark標(biāo)記gc root可達(dá)對(duì)象，然后CMS-concurrent-preclean重新并發(fā)掃描進(jìn)入到老年代的對(duì)象，最后時(shí)CMS-concurrent-abortable-preclean該階段并發(fā)運(yùn)行至eden區(qū)空間占用率達(dá)到滿(mǎn)意：
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] 最后就到了最終標(biāo)記階段，該階段會(huì)STW，從日志輸出可以看出新生代占用2048k，當(dāng)前這個(gè)重新標(biāo)記階段Rescan 花費(fèi)了0.0004620 secs，其余就是處理弱引用、卸載無(wú)用的類(lèi)以及清理元數(shù)據(jù)等花費(fèi)時(shí)間和耗時(shí)：
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]最后就是并發(fā)的清理垃圾會(huì)重置標(biāo)記，等待下一個(gè)周期的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] 最后我們查看內(nèi)存使用情況可以看到，新生代的2M就是我們最后分配的數(shù)組，在eden區(qū)，而老年代使用了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的區(qū)別
- Minor GC:發(fā)生在年輕代的空間回收，包含eden和survivor，也叫做Young GC。
- Major GC:在老年代堆區(qū)進(jìn)行空間回收。
- Full GC:清理所有堆區(qū)的內(nèi)存空間的垃圾內(nèi)存，包括年輕代和老年代。
四、頻繁的 minor gc 和major gc
1.問(wèn)題復(fù)現(xiàn)
我們嘗試編寫(xiě)一個(gè)程序，設(shè)置該程序的堆內(nèi)存新生代為5M，按照8:1:1的比例分配，這也就意為著Eden區(qū)內(nèi)存大小為4M，然后S區(qū)分別是512K，這也就意味著在待分配對(duì)象加Eden區(qū)堆空間超過(guò)4M就會(huì)觸發(fā)minor gc：
基于上述說(shuō)法，我們給出下面這段代碼：
public static void main(String[] args) throws Exception {
while (true) {
//分配3M數(shù)組
byte[] bytes = new byte[1024 * 1024];
bytes = new byte[1024 * 1024];
bytes = new byte[1024 * 1024];
//創(chuàng)建2M的新對(duì)象觸發(fā)GC
byte[] byte2 = new byte[2 * 1024 * 1024];
Thread.sleep(1000);
}
}為了演示年輕代的回收行為，我們需要在對(duì)這個(gè)應(yīng)用程序的年輕代堆內(nèi)存改為5M，且Eden區(qū)和S區(qū)的比例為8:1:1，同時(shí)也打印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輸出結(jié)果如下，GC日志顯示每秒基本都會(huì)觸發(fā)一次Minor GC，進(jìn)而間接導(dǎo)致頻繁的major gc:
2.問(wèn)題拆解與修復(fù)
結(jié)合我們的配置可知，我們頻繁分配對(duì)象導(dǎo)致新生代進(jìn)行頻繁的GC，又因?yàn)镾區(qū)大小無(wú)法容納存活的對(duì)象，進(jìn)而使得這些對(duì)象提前進(jìn)入老年代，導(dǎo)致major GC也隨之頻繁，所以解決的辦法也比較簡(jiǎn)單，按照等比例調(diào)整大堆空間，即將新生代堆空間調(diào)整至10M，保證S區(qū)各有2M空間以容納新生代存活的對(duì)象：
-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可以看到經(jīng)過(guò)調(diào)整之后，基本上Minor gc就能解決問(wèn)題：
3.將年輕代空間調(diào)大，是否會(huì)更加耗時(shí)？
答案是不會(huì)的，原因有以下兩點(diǎn)：
- JVM操作本質(zhì)上都是內(nèi)存操作，相對(duì)而言不會(huì)太慢。
- 我們將一次GC的時(shí)間拆分為t1和t2，t1是掃描年輕代空間是否有垃圾的時(shí)間，這個(gè)時(shí)間的幾乎可以忽略不計(jì)。而t2則是將eden空間存活的對(duì)象復(fù)制到survivor區(qū)的時(shí)間，這個(gè)復(fù)制操作則是t1時(shí)間的10倍。
由此可以看出，避免耗時(shí)的正確做法是合理評(píng)估新生代堆空間，減少非必要的復(fù)制操作，所以說(shuō)調(diào)整新生代的空間并不會(huì)導(dǎo)致進(jìn)一步的耗時(shí)問(wèn)題。
五、頻繁的FULL GC
1.復(fù)現(xiàn)問(wèn)題
我們現(xiàn)在模擬一個(gè)場(chǎng)景，我們的應(yīng)用中有一個(gè)定時(shí)任務(wù)，這個(gè)定時(shí)任務(wù)每隔1s會(huì)想另一個(gè)定時(shí)任務(wù)線(xiàn)程池中提交100個(gè)任務(wù)，每個(gè)任務(wù)都會(huì)針對(duì)Obj 對(duì)象進(jìn)行方法調(diào)用：
@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() {
//這個(gè)方法什么也不做
}
//返回count個(gè)Obj對(duì)象
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秒執(zhí)行一次
public void execute() {
logger.info("1s一次定時(shí)任務(wù)");
//向線(xiàn)程池提交100個(gè)任務(wù)
Obj.getObjList(100).forEach(i -> executor.scheduleWithFixedDelay(
i::func, 2, 3, TimeUnit.SECONDS
));
}
}完成后我們?cè)O(shè)置下面這段JVM參數(shù)后，將其啟動(dòng)：
-Xms20M -Xmx20M -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps不久后，控制臺(tái)出現(xiàn)頻繁的full gc，如果在生產(chǎn)環(huán)境，頻繁的full gc導(dǎo)致stw會(huì)導(dǎo)致系統(tǒng)吞吐量下降：
.......
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.排查思路
我們定位到程序號(hào)后，使用jstat -gc pid10000 10觀(guān)察其gc情況，可以看到每隔10s，就會(huì)增加大量的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查看堆區(qū)使用情況，可以看到老年代的使用率還是蠻高的：
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.在排除內(nèi)存泄漏的問(wèn)題后，我們通過(guò)jmap定位進(jìn)程中導(dǎo)致是什么對(duì)象導(dǎo)致老年代堆區(qū)被大量占用：
jmap -histo 7476 | head -n 20可以看到前20名中的對(duì)象都是和定時(shí)任務(wù)相關(guān)，有一個(gè)Task$Obj對(duì)象非常搶眼，很明顯就是因?yàn)樗臄?shù)量過(guò)多導(dǎo)致的，此時(shí)我們就可以通過(guò)定位代碼確定如何解決，常見(jiàn)方案無(wú)非是: 優(yōu)化代碼、增加空間兩種方式，一般來(lái)說(shuō)我們都會(huì)采用代碼優(yōu)化的方式去解決。
$
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而本次問(wèn)題也很明顯，任務(wù)是一個(gè)個(gè)提交到定時(shí)任務(wù)線(xiàn)程池中，是由于定時(shí)任務(wù)隊(duì)列DelayedWorkQueue不斷堆積任務(wù)導(dǎo)致內(nèi)存被打滿(mǎn)。所以最終改成將一個(gè)批處理一次性提交到定時(shí)任務(wù)中立刻將這一批對(duì)象回收從而避免耗時(shí)任務(wù)堆積一堆對(duì)象：
@Scheduled(cron = "0/1 * * * * ? ") //每1秒執(zhí)行一次
public void execute() {
logger.info("1s一次定時(shí)任務(wù)");
//向線(xiàn)程池提交100個(gè)任務(wù)
executor.scheduleWithFixedDelay(() -> {
Obj.getObjList(100).forEach(i -> i.func());
}, 2, 3, TimeUnit.SECONDS
);
}3.頻繁FULL GC的原因和解決對(duì)策
總的來(lái)說(shuō)原因可以頻繁FULL GC分為3個(gè):
- 用戶(hù)頻繁調(diào)用System.gc():這種情況需要修改代碼即可，我們不該頻繁調(diào)用這個(gè)方法的。
- 老年區(qū)空間過(guò)小:視情況適當(dāng)擴(kuò)大空間。
- 大對(duì)象過(guò)多:這種情況視情況決定是擴(kuò)大老年代空間或者將大對(duì)象拆分。
一般來(lái)說(shuō)，我們優(yōu)先考慮調(diào)整堆內(nèi)存空間，其次才是針對(duì)業(yè)務(wù)邏輯的代碼處理進(jìn)行更進(jìn)一步的優(yōu)化。
