數(shù)據(jù)家,idc官網(wǎng),算力,裸金屬,高電機房,邊緣算力,云網(wǎng)合一,北京機房,北京云計算,北京邊緣計算,北京裸金屬服務(wù)器,北京數(shù)據(jù)服務(wù)器,北京GPU服務(wù)器,高算力服務(wù)器,數(shù)據(jù)機房相關(guān)技術(shù)新聞最新報道
深夜，小菜同學(xué)突然被一陣急促的報警聲吵醒，原來是手機收到了一連串關(guān)于容器內(nèi)存使用率過高的報警信息。趕緊打開電腦查看服務(wù)器狀態(tài)，發(fā)現(xiàn)容器內(nèi)存使用率持續(xù)高達99%，下面把排查的過程和分析記錄下來，以供大家參考。
接收到系統(tǒng)的報警后，小菜同學(xué)立即檢查了容器狀態(tài)，觀察到以下現(xiàn)象：
Full GC（也可能是Major GC）后恢復(fù)了正常。服務(wù)使用的配置如下：
主要啟動參數(shù)：-Xms4g -Xmx4g -Xmn2g -XX:+UseG1GC -XX:G1HeapRegionSize=8m -XX:G1ReservePercent=15 -XX:InitiatingHeapOccupancyPercent=50
容器配置：4C5G
雖然容器內(nèi)存已經(jīng)使用了99%，但是JVM堆使用率在經(jīng)過一次Full GC后已經(jīng)降到了50%之后，所以并沒有立馬重啟服務(wù)，還是先來看看造成Full GC的原因。
鑒于堆使用率已經(jīng)恢復(fù)正常，查看當時的內(nèi)存快照意義不大，因此決定首先從觀察到的現(xiàn)象入手。因為凌晨1點的時候系統(tǒng)的流量不會很大，所以大概率是因為定時任務(wù)造成了，先排查報警服務(wù)凌晨1點執(zhí)行的定時任務(wù)。幸運的是調(diào)度平臺當時只有一個定時任務(wù)在執(zhí)行，立馬查看對應(yīng)的邏輯，發(fā)現(xiàn)了以下代碼片段中潛在的問題（簡化之后）：
public void job() {
// ... do business
int pageSize = 500;
while ( xxx ) {
// 每次查詢500個訂單
List orderNoList = orderService.getOrderPage(pageSize);
// 查詢500個訂單對應(yīng)的賬單
List orderBills = billService.findByOrderNos(orderNoList);
// ... do business
}
// ... do business
} 由于大部分訂單包含12至24期賬單，導(dǎo)致此處的orderBills在平均情況下含有數(shù)千至數(shù)萬條數(shù)據(jù)。經(jīng)過粗略估算，這些對象的總大小大約為5MB左右。
看啟動參數(shù)中G1HeapRegionSize=8m，代表每個Region的大小為8M，G1 GC會將大于Region一半大小的對象直接分配到老年代。所以orderBills對象會被直接分配到老年代，這也和在凌晨1點的時候年輕代使用無明顯波動，老年代使用有直線上漲的現(xiàn)象相符合。在后續(xù)的循環(huán)中，由于垃圾收集器清理的速度趕不上內(nèi)存分配的速度，導(dǎo)致垃圾逐漸積累并最終填滿整個堆空間，觸發(fā)了Full GC。
不過小菜同學(xué)有點疑惑為什么GC之后容器的內(nèi)存還是一直居高不下呢？
經(jīng)過一番查閱資料，原來JVM啟動時并不會立即實際占用全部Xms指定的內(nèi)存。Xms參數(shù)指定的是堆的初始大小，JVM會按照這個值預(yù)留內(nèi)存空間，但實際上只有在需要時才會逐漸使用這些預(yù)留的內(nèi)存。
JVM在完成內(nèi)存釋放后，是否將釋放的內(nèi)存返回給操作系統(tǒng)，這一行為取決于具體的JVM實現(xiàn)及其采用的垃圾回收策略。在很多情況下，JVM在進行垃圾收集并釋放了堆內(nèi)存之后，并不會立即將這部分內(nèi)存歸還給操作系統(tǒng)。相反，它會保留這部分內(nèi)存以備將來Java應(yīng)用程序的使用，因為從操作系統(tǒng)重新申請內(nèi)存通常會比從JVM內(nèi)部管理的內(nèi)存分配更為昂貴（時間成本上）。所以一般程序還會將Xms和Xmx配置為相等的大小，避免頻繁申請和釋放內(nèi)存造成的性能開銷。
idc網(wǎng),算力,裸金屬,高電機房,邊緣算力,云網(wǎng)合一,北京機房,北京云計算,北京邊緣計算,北京裸金屬服務(wù)器,北京數(shù)據(jù)服務(wù)器,北京GPU服務(wù)器,高算力服務(wù)器,數(shù)據(jù)機房上面兩個問題找到原因了，小菜同學(xué)決定在本地復(fù)現(xiàn)一下進行驗證。
新建一個memorytest項目，寫一個方法模擬內(nèi)存分配：
/**
* 模擬內(nèi)存分配
* @param num 循環(huán)次數(shù)
* @param size 每次分配幾MB的數(shù)據(jù)
*/
@RequestMapping("/memory/add/{num}/{size}")
public String add(@PathVariable("num") Integer num, @PathVariable("size") Integer size) {
for (int i = 0; i < num; i++) {
// 模擬查詢出來的大對象
byte[] allocation = new byte[size * 1024 * 1024];
}
return "";
}用以下命令啟動：
java -Xms2g -Xmx2g -Xmn1g -XX:+UseG1GC -XX:G1HeapRegionSize=8m -XX:G1ReservePercent=15 -XX:InitiatingHeapOccupancyPercent=50 -jar memorytest-0.0.1-SNAPSHOT.jar使用Jdk自帶的命令查詢JVM內(nèi)存分配情況，先使用jps -l查詢進程ID:
jps -l
16988 sun.tools.jps.Jps
9068 memorytest-0.0.1-SNAPSHOT.jar使用jmap -heap 查詢堆內(nèi)存分配：
jmap -heap 9068
Heap Usage:
G1 Heap:
regions = 256
capacity = 2147483648 (2048.0MB)
used = 230686720 (220.0MB)
free = 1916796928 (1828.0MB)
10.7421875% used
G1 Young Generation:
Eden Space:
regions = 26
capacity = 1115684864 (1064.0MB)
used = 218103808 (208.0MB)
free = 897581056 (856.0MB)
19.548872180451127% used
Survivor Space:
regions = 2
capacity = 16777216 (16.0MB)
used = 16777216 (16.0MB)
free = 0 (0.0MB)
100.0% used
G1 Old Generation:
regions = 0
capacity = 1015021568 (968.0MB)
used = 0 (0.0MB)
free = 1015021568 (968.0MB)
0.0% used使用jstat -gcutil 1秒1次監(jiān)控堆內(nèi)存使用和GC情況（也可以使用jconsole可視化處理工具來查看內(nèi)存的使用情況）：
jstat -gcutil 9068 1000
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 100.00 21.80 0.00 94.17 88.38 1 0.023 0 0.000 0.023該命令返回的主要的參數(shù)的意義：S0：Survivor space 0區(qū)的使用率。S1：Survivor space 1區(qū)的使用率。E：Eden區(qū)的使用率。O：Old區(qū)（老年代）的使用率。YGC：年輕代垃圾收集事件的次數(shù)。YGCT：年輕代垃圾收集所耗費的時間（秒）。FGC：Full GC（全堆垃圾收集）事件的次數(shù)。FGCT：Full GC所耗費的時間（秒）。GCT：垃圾收集所耗費的總時間（秒）。
此時使用ps aux --sort -rss查看Java進程占用的本機內(nèi)存才370MB左右，并沒有直接占用Xms設(shè)置的2g。
ps aux --sort -rss
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 9068 5.4 9.9 4718036 374536 pts/1 Sl+ 15:10 0:09 java -Xms2g -Xmx2g -Xmn1g -XX:+UseG1GC -XX:G1HeapRegionSize=8m -XX:G1ReservePercent=15 -XX:InitiatingHeapOccupancyPercent=50 -jar memorytest-0.0.1-SNAPSHOT.jar該命令返回的主要的參數(shù)的意義：PID: 進程ID。%CPU: 進程使用的CPU百分比。%MEM: 進程使用的物理內(nèi)存百分比。RSS: 進程當前占用的物理內(nèi)存大小，單位通常是KB。COMMAND: 啟動進程的命令行命令。
開始模擬業(yè)務(wù)分配內(nèi)存，為了方便觀察直接循環(huán)100000次，每次分配5MB空間：
http://127.0.0.1:8080/memory/add/100000/5jstat此時監(jiān)控到內(nèi)存情況：
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 100.00 24.81 0.00 94.17 88.38 1 0.023 0 0.000 0.023
0.00 0.00 1.48 61.36 93.38 89.74 12 0.192 0 0.000 0.192
0.00 100.00 1.49 86.37 92.74 89.74 33 0.294 0 0.000 0.294
0.00 0.00 2.27 99.41 92.74 89.74 56 0.395 0 0.000 0.395
0.00 0.00 2.15 99.55 92.75 89.74 84 0.522 0 0.000 0.522
0.00 0.00 1.94 99.77 92.20 89.00 119 0.663 0 0.000 0.663
0.00 0.00 4.00 99.71 92.21 89.01 169 0.834 0 0.000 0.834
0.00 100.00 0.75 21.43 92.22 89.01 232 0.998 1 0.051 1.049
0.00 100.00 0.84 99.68 92.22 89.01 252 1.025 1 0.051 1.077
0.00 100.00 0.88 99.87 92.25 89.01 274 1.064 1 0.051 1.115
0.00 0.00 1.48 70.73 92.25 89.01 299 1.110 1 0.051 1.161
0.00 0.00 1.48 75.90 92.25 89.01 327 1.168 1 0.051 1.219
0.00 0.00 1.77 99.81 92.25 89.01 361 1.239 1 0.051 1.290
0.00 0.00 2.41 99.92 92.27 89.01 409 1.340 1 0.051 1.392此時可以看到對象都直接分配到了老年代，年輕代的內(nèi)存使用沒有多大的變化，并且當YGC（Young Generation Garbage Collection，年輕代垃圾回收）來不及回收時就會發(fā)生FGC（Full Garbage Collection，全堆垃圾回收）。
此時再使用ps aux --sort -rss查看Java進程占用的本機內(nèi)存已經(jīng)到了2G了，并且在方法執(zhí)行完成后（也包括FGC后）也沒有釋放此內(nèi)存。
ps aux --sort -rss
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 9068 77.1 60.4 4720084 2043996 pts/1 Sl+ 15:10 6:03 java -Xms2g -Xmx2g -Xmn1g -XX:+UseG1GC -XX:G1HeapRegionSize=8m -XX:G1ReservePercent=15 -XX:InitiatingHeapOccupancyPercent=50 -jar memorytest-0.0.1-SNAPSHOT.jar再模擬一次業(yè)務(wù)分配內(nèi)存，為了方便觀察直接循環(huán)100000次，這次每次分配2MB空間：
http://127.0.0.1:8080/memory/add/100000/2jstat此時監(jiān)控到內(nèi)存情況：
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 100.00 15.04 0.00 94.14 88.45 1 0.027 0 0.000 0.027
0.00 100.00 15.04 0.00 94.14 88.45 1 0.027 0 0.000 0.027
0.00 100.00 93.18 0.00 93.15 89.36 2 0.043 0 0.000 0.043
0.00 100.00 51.49 0.66 93.15 89.36 22 0.146 0 0.000 0.146
0.00 0.00 68.15 1.48 93.15 89.36 44 0.167 0 0.000 0.167
0.00 0.00 81.48 1.48 93.15 89.36 66 0.186 0 0.000 0.186
0.00 0.00 16.30 1.48 93.15 89.36 89 0.207 0 0.000 0.207
0.00 0.00 58.52 1.48 93.15 89.36 111 0.226 0 0.000 0.226
0.00 0.00 4.44 1.48 93.16 89.36 134 0.246 0 0.000 0.246
0.00 100.00 50.00 0.66 93.16 89.36 156 0.265 0 0.000 0.265
0.00 0.00 88.15 1.49 93.16 89.36 178 0.284 0 0.000 0.284
0.00 0.00 41.48 1.49 93.16 89.36 201 0.305 0 0.000 0.305
0.00 0.00 87.41 1.49 93.16 89.36 223 0.324 0 0.000 0.324
0.00 0.00 27.41 1.49 93.17 89.36 246 0.344 0 0.000 0.344
0.00 0.00 89.63 1.49 93.17 89.36 263 0.358 0 0.000 0.358
0.00 0.00 89.63 1.49 93.17 89.36 263 0.358 0 0.000 0.358此時很明顯可以看到對象都直接分配到了年輕代，年輕代的回收效率也比老年代高，并且沒有產(chǎn)生FGC。
再結(jié)合本次報警的現(xiàn)象，解決辦法也呼之欲出：
JConsole、VisualVM等）觀察不同Region大小設(shè)置下的GC表現(xiàn)和應(yīng)用吞吐量，以找到最佳平衡點。JVM內(nèi)存問題可能不常有，但是一旦發(fā)生可能對我們系統(tǒng)造成極大的影響，此次內(nèi)存飆升也給我們敲響了警鐘，發(fā)現(xiàn)了我們在這邊注重的不夠，很多監(jiān)控和日志并不完整，如啟動參數(shù)中沒有加上發(fā)生OOM時自動dump文件的參數(shù)等。好在此次服務(wù)未受到影響，所有有足夠的時候給我們?nèi)ヅ挪楹万炞C。特此結(jié)合此次排查的過程的一些收獲記錄一下，假設(shè)下次還有發(fā)生可以有所參考：
#jmap命令保存整個Java堆（在你dump的時間不是事故發(fā)生點的時候尤其推薦）
jmap -dump:format=b，file=heap.bin
#jmap命令只保存Java堆中的存活對象， 包含live選項，會在堆轉(zhuǎn)儲前執(zhí)行一次Full GC
jmap -dump:live，format=b，file=heap.bin
#jcmd命令保存整個Java堆，Jdk1.7后有效
jcmd GC.heap_dump filename=heap.bin 還有在啟動參數(shù)中添加發(fā)生OOM時自動生成heapdump的參數(shù):-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/tmp/heap.bin啟動參數(shù)中添加GC日志打印相關(guān)的參數(shù)：
# Java8及以下
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:
# Java9及以上
-Xlog:gc*::time arthas等）：jstat -gcutil ：監(jiān)視Java堆狀況，主要關(guān)注已使用空間的百分比和GC情況
jmap -heap ：顯示Java堆詳細信息
jmap -histo[:live] ：顯示堆中對象統(tǒng)計信息：快速識別哪些類的實例占用了大量的堆內(nèi)存 StackOverflowError異常，需要著重檢查是否有死循環(huán)或者代碼調(diào)用鏈路不合理。面對內(nèi)存使用率的異常，我們不僅要關(guān)注即時的解決方案，還需要考慮如何從根本上避免此類問題的再次發(fā)生。如使用優(yōu)化數(shù)據(jù)結(jié)構(gòu)、減少不必要的計算、采用懶加載等策略，以及建立細致的內(nèi)存監(jiān)控體系等。性能優(yōu)化不應(yīng)該僅僅是面對問題時的臨時行動，而應(yīng)該成為開發(fā)文化的一部分。