JVM小冊(1)------jstat和Parallel GC日誌

劍小純發表於2021-04-30
JVMJSParallelGC

JVM小冊(1)------jstat和Parallel GC日誌

一. 背景

在生產環境中,有時候會遇到OOM的情況,拋開Arthas 等比較成熟的工具以外,我們可以使用java 提供的jatat和jps、jmap等工具來幫助我們排查問題和定位原因,本系列小冊先簡單記錄一下實際使用方式,後續對JVM進行分析.

二. 場景舉例

比如目前有一臺伺服器,部署了一個java服務,我們為它分配的堆記憶體如下:

#最大堆記憶體4G,最小2G, 一般來說建議這2個引數設定成一樣的,減少因為GC以後動態記憶體擴容對系統造成的開銷
-Xmx4096M -Xms2048M

那麼怎麼來檢視這個服務在執行過程中的GC情況和JVM中記憶體的使用情況呢?

1. 新增JVM引數

首先我們要在jar包啟動的時候新增列印GC日誌 的引數,這裡引數如下:

#列印GC詳細資訊
-XX:+PrintGCDetails
#列印GC時間
-XX:+PrintGCTimeStamps
#輸出GC日誌
-Xloggc:gc.log

新增完以上三個引數以後,在jar啟動後,會在你-Xloggc 引數指定位置生成對應的gc日誌,如下:

image-20210426112024708

日誌的內容我們等下再詳細講解.接下來比如我們以上配置的java服務傳送了OOM,或者你監控發現該服務的記憶體佔用持續走高, 這個時候我們可能會去排查原因.

2. 使用jps 命令檢視java程式的PID

在該服務部署的伺服器上,執行命令jps,你可能會得到以下資訊:

6 xxx.jar
366 Jps

上面的返回結果中,第一行表示當前執行的一個java程式,前面的數字是該程式的PID,下面一行是Jps命令本身,不用管.

3. 使用jstat命令檢視JVM記憶體活動

根據第二步查到的該服務的PID是6, 我們就可以用jstat命令去檢視記憶體活動,命令如下:

/opt/app # jstat -gc 6 1000 100

命令解釋: 間隔1秒列印100次PID為6的java程式的gc情況

列印結果如下:

image-20210426113609789

其實jstat命令除了-gc引數外,還有很多可選,這裡先不做擴充套件.現在我們得到的結果要怎麼看呢?

4. jstat結果解釋

以上的圖片中,每一個指標的解釋如下:

 S0C       From Survivor區大小(位元組)
 S1C       To Survivor區大小(位元組)
 S0U       From Survivor區當前使用的記憶體大小(位元組)
 S1U       To Survivor區當前使用的記憶體大小(位元組)
 EC        Eden區的大小(位元組)
 EU        Eden區當前使用大小(位元組)
 OC        老年代大小(位元組)
 OU        老年代當前使用大小(位元組)
 MC        方法區(永久代,後設資料區)大小(位元組)
 MU        方法區當前使用的大小(位元組)
 CCSC      當前壓縮類空間的容量
 CCSU      當前壓縮類空間也是用的容量
 YGC       系統執行迄今為止的YoungGC次數
 YGCT      YoungGC耗時
 FGC       系統執行迄今為止的Full GC次數
 FGCT      FullGC耗時
 GCT       所有GC總耗時
5. 根據GC情況分析

根據jstat檢視出來的gc情況,我們可能需要得到以下幾個指標:

新生代物件增長的速率:
YoungGC的觸發頻率:
YoungGC的耗時:
每次YoungGC後有多少物件存活下來:
每次YoingGC後有多少物件進入了老年代:
老年代物件增長的速率:
FullGC觸發頻率:
FullGC的耗時:

根據以上引數,再加上對JVM記憶體模型的認識,我們可以清楚的知道當前jvm程式的執行情況,有助於我們對問題的定位.

6. GC日誌分析

  • 對於已經啟動的jvm程式,我們可以使用如下命令檢視當前jvm使用的引數,版本,以及垃圾回收器等資訊:

    java -XX:+PrintCommandLineFlags -version

  • 也可以使用如下命令檢視當前jvmGC的詳細資訊

    java -XX:+PrintGCDetails -version
1) Parallel Scavenge + Serial Old GC日誌分析

接著回過頭來說gc日誌,我們之前在jar啟動引數中加入了列印gc資訊的引數.在jvm啟動以後,會在我們指定的目錄列印gc日誌,我們開啟剛才那個應用的gc日誌,你可能會看到以下資訊:

OpenJDK 64-Bit Server VM (25.212-b04) for linux-amd64 JRE (1.8.0_212-b04), built on May  4 2019 17:56:12 by "buildozer" with gcc 8.3.0
Memory: 4k page, physical 5120000k(5118348k free), swap 0k(0k free)

CommandLine flags: -XX:InitialHeapSize=2147483648 -XX:MaxHeapSize=4294967296 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 

4.737: [GC (Metadata GC Threshold) [PSYoungGen: 367429K->23240K(611840K)] 367429K->23256K(2010112K), 0.0300742 secs] [Times: user=0.04 sys=0.01, real=0.03 secs] 

4.768: [Full GC (Metadata GC Threshold) [PSYoungGen: 23240K->0K(611840K)] [ParOldGen: 16K->22304K(1398272K)] 23256K->22304K(2010112K), [Metaspace: 20775K->20775K(1067008K)], 0.0600170 secs] [Times: user=0.09 sys=0.00, real=0.06 secs] 

6.329: [GC (Allocation Failure) [PSYoungGen: 524800K->8127K(611840K)] 547104K->30439K(2010112K), 0.0197683 secs] [Times: user=0.04 sys=0.00, real=0.02 secs] 

7.776: [GC (Allocation Failure) [PSYoungGen: 532927K->18132K(611840K)] 555239K->40444K(2010112K), 0.0574908 secs] [Times: user=0.04 sys=0.00, real=0.06 secs] 

8.528: [GC (Allocation Failure) [PSYoungGen: 542932K->16422K(928256K)] 565244K->38742K(2326528K), 0.0376001 secs] [Times: user=0.09 sys=0.00, real=0.03 secs] 

8.755: [GC (GCLocker Initiated GC) [PSYoungGen: 184691K->9923K(928256K)] 207011K->32243K(2326528K), 0.0178837 secs] [Times: user=0.04 sys=0.01, real=0.02 secs] 

8.859: [GC (Metadata GC Threshold) [PSYoungGen: 91421K->8481K(1247232K)] 113741K->30801K(2645504K), 0.0144768 secs] [Times: user=0.03 sys=0.01, real=0.01 secs]

8.873: [Full GC (Metadata GC Threshold) [PSYoungGen: 8481K->0K(1247232K)] [ParOldGen: 22320K->16585K(1398272K)] 30801K->16585K(2645504K), [Metaspace: 34975K->34975K(1081344K)], 0.1082484 secs] [Times: user=0.20 sys=0.01, real=0.11 secs] 

10.761: [GC (Allocation Failure) [PSYoungGen: 1223168K->15163K(1247744K)] 1239753K->31748K(2646016K), 0.0446415 secs] [Times: user=0.05 sys=0.02, real=0.04 secs]

13.097: [GC (Allocation Failure) [PSYoungGen: 1238331K->23551K(1343488K)] 1254916K->68603K(2741760K), 0.1209356 secs] [Times: user=0.14 sys=0.02, real=0.13 secs]

15.171: [GC (Allocation Failure) [PSYoungGen: 1343487K->38905K(1358848K)] 1388539K->99859K(2757120K), 0.1189547 secs] [Times: user=0.15 sys=0.02, real=0.12 secs] 

17.227: [GC (Allocation Failure) [PSYoungGen: 1358841K->23895K(1339392K)] 1419795K->104346K(2737664K), 0.0751066 secs] [Times: user=0.11 sys=0.01, real=0.07 secs] 

18.043: [GC (Metadata GC Threshold) [PSYoungGen: 414691K->7705K(1349120K)] 495143K->100326K(2747392K), 0.0331763 secs] [Times: user=0.05 sys=0.00, real=0.03 secs] 

18.077: [Full GC (Metadata GC Threshold) [PSYoungGen: 7705K->0K(1349120K)] [ParOldGen: 92620K->56466K(1398272K)] 100326K->56466K(2747392K), [Metaspace: 57545K->57545K(1101824K)], 0.2955924 secs] [Times: user=0.52 sys=0.01, real=0.30 secs] 

21.465: [GC (Allocation Failure) [PSYoungGen: 1300480K->27367K(1348096K)] 1356946K->83834K(2746368K), 0.0575351 secs] [Times: user=0.09 sys=0.00, real=0.06 secs] 

30.452: [Full GC (Metadata GC Threshold) [PSYoungGen: 15506K->0K(1351168K)] [ParOldGen: 90168K->76729K(1721856K)] 105674K->76729K(3073024K), [Metaspace: 95611K->95607K(1136640K)], 0.3909874 secs] [Times: user=0.69 sys=0.01, real=0.39 secs] 

94.216: [GC (Allocation Failure) [PSYoungGen: 1307648K->23645K(1350656K)] 1384377K->100382K(3072512K), 0.0587363 secs] [Times: user=0.14 sys=0.00, real=0.06 secs]

對於以上日誌,我們應該怎麼分析檢視呢?

這裡我們為了排除干擾,我手動將日誌進行了換行, 並且,一些同型別的日誌我都刪掉了,這樣做的原因是我們先一起來看下這個日誌的構成以及如何檢視.知道如何檢視以後,可以再根據日誌的時間線來分析日誌.

那麼上面的日誌我簡化成如下部分:

image-20210426141954740

可以看到,我簡化後,將日誌劃分成了14句,下面我們依次來看:

1

OpenJDK 64-Bit Server VM (25.212-b04) for linux-amd64 JRE (1.8.0_212-b04), built on May  4 2019 17:56:12 by "buildozer" with gcc 8.3.0
Memory: 4k page, physical 5120000k(5118348k free), swap 0k(0k free)

這一部分主要是表明當前java虛擬機器的版本、JDK的版本還有伺服器的系統核心等引數.

2

CommandLine flags: -XX:InitialHeapSize=2147483648 -XX:MaxHeapSize=4294967296 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC

這一句日誌中表明當前JVM採用的引數是哪些.如果不設定jvm引數, 也可以通過這部分日誌來得出當前jvm預設的引數.可以看到當前我們使用的垃圾回收器是Parallel, 這也是1.8預設的垃圾回收器.

3

4.737: [GC (Metadata GC Threshold) [PSYoungGen: 367429K->23240K(611840K)] 367429K->23256K(2010112K), 0.0300742 secs] [Times: user=0.04 sys=0.01, real=0.03 secs]

  • 4.737:

    表示GC發生的時間,這裡顯示的是秒級別的時間,如果你再jvm啟動的時候加入了引數-XX:+PrintGCDateStamps它也會列印出當前GC的具體日期.

  • [GC (Metadata GC Threshold)

    這裡表示當前發生GC的原因,在這裡是由於Metadata區導致的GC. 但是在這裡我很疑惑,1.8中,jvm中的永久代便用Metadata元空間來取代了,而元空間的記憶體使用的是堆外記憶體,既然如此,為什麼元空間會不足呢?

    查閱資料後發現,在預設情況下,元空間大小的預設值是21810376B,也就是大約20M左右.

    檢視當前jvm初始化引數命令: java -XX:+PrintFlagsInitial

    如果要自定義元空間的大小,可以使用引數-XX:MetaspaceSize=128M來設定.

  • [PSYoungGen: 367429K->23240K(611840K)]

    這一句的意思是,Young去發生了GC,在GC前Young區是367429k,在GC後是23240k,(611840k)標識Yuong區總大小.

  • 367429K->23256K(2010112K)

    這句的意思是,堆記憶體在GC前的大小-->GC後的大小(堆記憶體總大小)

  • 0.0300742 secs

    這裡表示本次GC的持續時間是0.0300742秒

  • [Times: user=0.04 sys=0.01, real=0.03 secs]

    這裡是本次GC的詳細的時間資訊

    1. real: 指的是在此次GC中所花費的總時間
    2. user: 指的是CPU工作在使用者態所花費的時間
    3. sys: 指的是CPU工作在核心態所花費的時間

    詳細的解釋可以參考StackOverflow的文章

    在這裡,user+sys是CPU花費的實際時間,這個值統計了所有CPU上的時間,如果程式在多執行緒的環境下,這個值是會超出real的值的,也就是user+sys>=real

    存在多執行緒的原因在於,在回收過程中,存在併發的GC演算法,比如ParNew和ParallelOld.

4

4.768: [Full GC (Metadata GC Threshold) [PSYoungGen: 23240K->0K(611840K)] [ParOldGen: 16K->22304K(1398272K)] 23256K->22304K(2010112K), [Metaspace: 20775K->20775K(1067008K)], 0.0600170 secs] [Times: user=0.09 sys=0.00, real=0.06 secs]

這部分日誌中,我們只對上面沒有提及的部分做說明.

  • Full GC (Metadata GC Threshold)

    表示當前傳送的是Full GC

  • [ParOldGen: 16K->22304K(1398272K)]

    表示老年代Old區傳送的垃圾回收,回收前的大小 -> 回收後的大小(Old區總大小)

  • [Metaspace: 20775K->20775K(1067008K)]

    表示元空間區域傳送的垃圾回收, 回收前是20775k,回收後是20775k,總大小是1067008k

基本上,到這裡的話,Parallel的GC日誌我們已經分析完了.下面開始CMS和ParNew垃圾回收器產生的GC日誌分析

2) ParNew + CMS GC日誌分析

JDK1.8預設使用的垃圾回收器是Parallel,該垃圾回收在進行GC時是單執行緒的,因此建議在生產環境中使用ParNew+CMS垃圾回收器.

-XX:+UseConcMarkSweepGC

使用以上JVM引數即可指定jvm的垃圾回收器為: 新生代ParNew老年代CMS,一般來說,我們會設定新生代的大小,以為預設情況下,有可能jvm預設的新生代很小,如果堆記憶體給了比較大的空間,新生代不做調整的話,浪費記憶體空間.

以下為我使用的jvm引數:

#使用ParNew+CMS垃圾回收器
-XX:+UseConcMarkSweepGC
#列印GC詳情
-XX:+PrintGCDetails
#列印GC的日期
-XX:+PrintGCDateStamps
#列印GC時間
-XX:+PrintGCTimeStamps
#指定GC日誌位置
-Xloggc:/opt/app/logs/gc.log
#指定最大堆記憶體
-Xmx2048M
#指定最小堆記憶體
-Xms2048M
#新生代和老年代的記憶體佔比1:2
-XX:NewRatio=2
#Eden區和Survivor比例8:1 
-XX:SurvivorRatio=8
#指定新生代的最小記憶體空間
-XX:NewSize=715784192
#指定新生代的最大記憶體空間
-XX:MaxNewSize=715784192

使用以上JVM引數以後,我們檢視gc日誌如下(可以使用less 檔名 的方式檢視gc日誌,PageUp向上翻頁,PageDown向下翻頁):

OpenJDK 64-Bit Server VM (25.212-b04) for linux-amd64 JRE (1.8.0_212-b04), built on May  4 2019 17:56:12 by "buildozer" with gcc 8.3.0
Memory: 4k page, physical 3072000k(3070320k free), swap 0k(0k free)
CommandLine flags: -XX:InitialHeapSize=2147483648 -XX:MaxHeapSize=2147483648 -XX:MaxNewSize=715784192 -XX:NewRatio=2 -XX:NewSize=715784192 -XX:OldPLABSize=16 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:Survivor
Ratio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC 
2021-04-29T16:37:58.684+0800: 5.799: [GC (Allocation Failure) 2021-04-29T16:37:58.684+0800: 5.799: [ParNew: 559232K->26278K(629120K), 0.0439056 secs] 559232K->26278K(2027264K), 0.0440200 secs] [Times: user=0.06 sys=0.01, real=0.04 secs] 
2021-04-29T16:37:58.728+0800: 5.843: [GC (CMS Initial Mark) [1 CMS-initial-mark: 0K(1398144K)] 41154K(2027264K), 0.0076770 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2021-04-29T16:37:58.736+0800: 5.851: [CMS-concurrent-mark-start]
2021-04-29T16:37:58.744+0800: 5.859: [CMS-concurrent-mark: 0.008/0.008 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
2021-04-29T16:37:58.744+0800: 5.859: [CMS-concurrent-preclean-start]
2021-04-29T16:37:58.747+0800: 5.862: [CMS-concurrent-preclean: 0.003/0.003 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2021-04-29T16:37:58.748+0800: 5.862: [CMS-concurrent-abortable-preclean-start]
2021-04-29T16:37:59.594+0800: 6.708: [CMS-concurrent-abortable-preclean: 0.458/0.846 secs] [Times: user=1.59 sys=0.08, real=0.85 secs] 
2021-04-29T16:37:59.594+0800: 6.708: [GC (CMS Final Remark) [YG occupancy: 394027 K (629120 K)]2021-04-29T16:37:59.594+0800: 6.709: [Rescan (parallel) , 0.1164667 secs]2021-04-29T16:37:59.710+0800: 6.825: [weak refs processing, 0.0000352 secs]2021-0
4-29T16:37:59.710+0800: 6.825: [class unloading, 0.0041990 secs]2021-04-29T16:37:59.715+0800: 6.829: [scrub symbol table, 0.0038982 secs]2021-04-29T16:37:59.719+0800: 6.833: [scrub string table, 0.0005058 secs][1 CMS-remark: 0K(1398144K)] 394027K(20
27264K), 0.1260089 secs] [Times: user=0.29 sys=0.00, real=0.12 secs] 
2021-04-29T16:37:59.720+0800: 6.835: [CMS-concurrent-sweep-start]
2021-04-29T16:37:59.720+0800: 6.835: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-04-29T16:37:59.720+0800: 6.835: [CMS-concurrent-reset-start]
2021-04-29T16:37:59.791+0800: 6.906: [CMS-concurrent-reset: 0.071/0.071 secs] [Times: user=0.07 sys=0.05, real=0.07 secs] 
2021-04-29T16:38:00.341+0800: 7.455: [GC (Allocation Failure) 2021-04-29T16:38:00.341+0800: 7.455: [ParNew: 585510K->23331K(629120K), 0.0716625 secs] 585510K->23331K(2027264K), 0.0717529 secs] [Times: user=0.14 sys=0.02, real=0.07 secs] 
2021-04-29T16:38:01.715+0800: 8.829: [GC (Allocation Failure) 2021-04-29T16:38:01.715+0800: 8.829: [ParNew: 582563K->36089K(629120K), 0.0958375 secs] 582563K->36089K(2027264K), 0.0959258 secs] [Times: user=0.14 sys=0.00, real=0.09 secs] 
2021-04-29T16:38:02.687+0800: 9.801: [GC (Allocation Failure) 2021-04-29T16:38:02.687+0800: 9.801: [ParNew: 595321K->29885K(629120K), 0.0493737 secs] 595321K->29885K(2027264K), 0.0494595 secs] [Times: user=0.12 sys=0.01, real=0.05 secs] 
2021-04-29T16:38:03.564+0800: 10.679: [GC (Allocation Failure) 2021-04-29T16:38:03.564+0800: 10.679: [ParNew: 589117K->38018K(629120K), 0.0469700 secs] 589117K->38018K(2027264K), 0.0470567 secs] [Times: user=0.11 sys=0.00, real=0.04 secs] 
2021-04-29T16:38:04.721+0800: 11.835: [GC (Allocation Failure) 2021-04-29T16:38:04.721+0800: 11.835: [ParNew: 597250K->38175K(629120K), 0.1040785 secs] 597250K->38175K(2027264K), 0.1041795 secs] [Times: user=0.10 sys=0.01, real=0.11 secs] 
2021-04-29T16:38:04.825+0800: 11.940: [GC (CMS Initial Mark) [1 CMS-initial-mark: 0K(1398144K)] 39294K(2027264K), 0.0224121 secs] [Times: user=0.04 sys=0.00, real=0.02 secs] 
2021-04-29T16:38:04.848+0800: 11.962: [CMS-concurrent-mark-start]
2021-04-29T16:38:04.856+0800: 11.970: [CMS-concurrent-mark: 0.008/0.008 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
2021-04-29T16:38:04.856+0800: 11.971: [CMS-concurrent-preclean-start]
2021-04-29T16:38:04.860+0800: 11.974: [CMS-concurrent-preclean: 0.004/0.004 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
2021-04-29T16:38:04.860+0800: 11.975: [CMS-concurrent-abortable-preclean-start]
2021-04-29T16:38:05.711+0800: 12.826: [CMS-concurrent-abortable-preclean: 0.779/0.851 secs] [Times: user=1.65 sys=0.07, real=0.85 secs] 
2021-04-29T16:38:05.711+0800: 12.826: [GC (CMS Final Remark) [YG occupancy: 331082 K (629120 K)]2021-04-29T16:38:05.711+0800: 12.826: [Rescan (parallel) , 0.0991187 secs]2021-04-29T16:38:05.810+0800: 12.925: [weak refs processing, 0.0000489 secs]202
1-04-29T16:38:05.810+0800: 12.925: [class unloading, 0.0068616 secs]2021-04-29T16:38:05.817+0800: 12.932: [scrub symbol table, 0.0083112 secs]2021-04-29T16:38:05.826+0800: 12.940: [scrub string table, 0.0006307 secs][1 CMS-remark: 0K(1398144K)] 3310
82K(2027264K), 0.1164628 secs] [Times: user=0.19 sys=0.00, real=0.12 secs] 
2021-04-29T16:38:05.828+0800: 12.942: [CMS-concurrent-sweep-start]
2021-04-29T16:38:05.828+0800: 12.942: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-04-29T16:38:05.828+0800: 12.942: [CMS-concurrent-reset-start]
2021-04-29T16:38:05.831+0800: 12.946: [CMS-concurrent-reset: 0.003/0.003 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2021-04-29T16:38:06.290+0800: 13.405: [GC (Allocation Failure) 2021-04-29T16:38:06.290+0800: 13.405: [ParNew: 597407K->58488K(629120K), 0.1068891 secs] 597407K->58488K(2027264K), 0.1069796 secs] [Times: user=0.14 sys=0.01, real=0.11 secs] 
2021-04-29T16:38:07.295+0800: 14.409: [GC (Allocation Failure) 2021-04-29T16:38:07.295+0800: 14.409: [ParNew: 617720K->53644K(629120K), 0.1625714 secs] 617720K->68440K(2027264K), 0.1626508 secs] [Times: user=0.24 sys=0.02, real=0.16 secs] 
2021-04-29T16:38:08.389+0800: 15.504: [GC (Allocation Failure) 2021-04-29T16:38:08.389+0800: 15.504: [ParNew: 612876K->35515K(629120K), 0.0610254 secs] 627672K->50311K(2027264K), 0.0611143 secs] [Times: user=0.16 sys=0.01, real=0.06 secs] 
2021-04-29T16:38:09.449+0800: 16.563: [GC (Allocation Failure) 2021-04-29T16:38:09.449+0800: 16.564: [ParNew: 594747K->37068K(629120K), 0.0614502 secs] 609543K->51864K(2027264K), 0.0615418 secs] [Times: user=0.09 sys=0.00, real=0.06 secs] 
2021-04-29T16:38:10.525+0800: 17.639: [GC (Allocation Failure) 2021-04-29T16:38:10.525+0800: 17.639: [ParNew: 596300K->37786K(629120K), 0.0698999 secs] 611096K->52582K(2027264K), 0.0699826 secs] [Times: user=0.12 sys=0.00, real=0.07 secs] 
2021-04-29T16:38:11.173+0800: 18.288: [GC (Allocation Failure) 2021-04-29T16:38:11.173+0800: 18.288: [ParNew: 597018K->36129K(629120K), 0.0386147 secs] 611814K->50925K(2027264K), 0.0386905 secs] [Times: user=0.07 sys=0.00, real=0.04 secs] 
2021-04-29T16:38:12.205+0800: 19.320: [GC (Allocation Failure) 2021-04-29T16:38:12.205+0800: 19.320: [ParNew: 595361K->42277K(629120K), 0.0603755 secs] 610157K->57073K(2027264K), 0.0604587 secs] [Times: user=0.10 sys=0.00, real=0.06 secs] 
2021-04-29T16:38:13.308+0800: 20.423: [GC (Allocation Failure) 2021-04-29T16:38:13.308+0800: 20.423: [ParNew: 601509K->48883K(629120K), 0.0707038 secs] 616305K->63679K(2027264K), 0.0707979 secs] [Times: user=0.12 sys=0.00, real=0.07 secs] 
2021-04-29T16:38:14.230+0800: 21.344: [GC (Allocation Failure) 2021-04-29T16:38:14.230+0800: 21.344: [ParNew: 608115K->47267K(629120K), 0.0806798 secs] 622911K->68980K(2027264K), 0.0807631 secs] [Times: user=0.11 sys=0.01, real=0.08 secs]

可以看到,在加入了以上的JVM引數以後,每次GC的時間都列印的很詳細,我們可以清楚的知道每一次gc的情況.下面對這段日誌進行分析.

image-20210430140944547

1

OpenJDK 64-Bit Server VM (25.212-b04) for linux-amd64 JRE (1.8.0_212-b04), built on May  4 2019 17:56:12 by "buildozer" with gcc 8.3.0
Memory: 4k page, physical 3072000k(3070320k free), swap 0k(0k free)
CommandLine flags: -XX:InitialHeapSize=2147483648 -XX:MaxHeapSize=2147483648 -XX:MaxNewSize=715784192 -XX:NewRatio=2 -XX:NewSize=715784192 -XX:OldPLABSize=16 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:Survivor
Ratio=8 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC

這一段依舊是說明當前JVM使用的一些引數,還有版本什麼的,不再多說

2

2021-04-29T16:37:58.684+0800: 5.799: [GC (Allocation Failure) 2021-04-29T16:37:58.684+0800: 5.799: [ParNew: 559232K->26278K(629120K), 0.0439056 secs] 559232K->26278K(2027264K), 0.0440200 secs] [Times: user=0.06 sys=0.01, real=0.04 secs] 
2021-04-29T16:37:58.728+0800: 5.843: [GC (CMS Initial Mark) [1 CMS-initial-mark: 0K(1398144K)] 41154K(2027264K), 0.0076770 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

整體的結構和之前的GC日誌相差並不大.

  • 2021-04-29T16:37:58.684+0800: 5.799:

    這段標識當前GC的時間

  • GC (Allocation Failure)

    表明當前GC的原因,在這裡傳送了2次,第一次是由於物件分配失敗,第二次是CMD的初始標記階段.因為CMS回收,即伴隨著一次YuongGC,會對記憶體中的物件進行標記,這一行就表明當前YuongGC是由於CMS的初始標記引起的.

  • [ParNew: 559232K->26278K(629120K), 0.0439056 secs]

    很明顯,ParNew回收器是收集年輕代的垃圾,這裡回收的就是年輕代的區域.

    這裡是說,年輕代回收前是559M左右,回收後是26M左右,總共大小是629M左右.

    後面的0.0439056 secs表明GC的耗時

  • 559232K->26278K(2027264K), 0.0440200 secs

    這段依舊是整個堆記憶體的佔用情況,分別是GC前--->GC後(整個堆的記憶體大小),耗費時間.

  • [Times: user=0.06 sys=0.01, real=0.04 secs]

    這段就不說了,上面已經說過了,是GC的三種時間

  • 2021-04-29T16:37:58.728+0800: 5.843: [GC (CMS Initial Mark) [1 CMS-initial-mark: 0K(1398144K)] 41154K(2027264K), 0.0076770 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

    這就是所謂的CMS的初始標記階段.標記所有可以到達GcRoot的物件

    CMS-initial-mark: 0K(1398144K)] 41154K(2027264K)

    這一句說明,老年代的總大小是1398144K,在佔用達到0K的時候觸發了CMS

3

2021-04-29T16:37:58.736+0800: 5.851: [CMS-concurrent-mark-start]
2021-04-29T16:37:58.744+0800: 5.859: [CMS-concurrent-mark: 0.008/0.008 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
2021-04-29T16:37:58.744+0800: 5.859: [CMS-concurrent-preclean-start]
2021-04-29T16:37:58.747+0800: 5.862: [CMS-concurrent-preclean: 0.003/0.003 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2021-04-29T16:37:58.748+0800: 5.862: [CMS-concurrent-abortable-preclean-start]
2021-04-29T16:37:59.594+0800: 6.708: [CMS-concurrent-abortable-preclean: 0.458/0.846 secs] [Times: user=1.59 sys=0.08, real=0.85 secs]

這一段其實就是FullGC了,我們知道,使用了CMS垃圾回收器以,Old去的回收就是CMS來做的 .

  • 2021-04-29T16:37:58.736+0800: 5.851: [CMS-concurrent-mark-start]

    這一段表示CMS的併發標記階段,在第一階段中停止的執行緒將再次啟動，並且在第一階段中標記的物件可傳遞到的所有物件都標記在這裡。

  • 2021-04-29T16:37:58.744+0800: 5.859: [CMS-concurrent-mark: 0.008/0.008 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]

    這一段是併發標記的時間位,可以看出併發標記的時間是0.008s

  • 2021-04-29T16:37:58.744+0800: 5.859: [CMS-concurrent-preclean-start] 2021-04-29T16:37:58.747+0800: 5.862: [CMS-concurrent-preclean: 0.003/0.003 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

    這兩條,上面的一條是標識當前的階段是CMS的併發預清理階段,下面一條記錄了時間

  • 2021-04-29T16:37:58.748+0800: 5.862: [CMS-concurrent-abortable-preclean-start] 2021-04-29T16:37:59.594+0800: 6.708: [CMS-concurrent-abortable-preclean: 0.458/0.846 secs] [Times: user=1.59 sys=0.08, real=0.85 secs]

    這兩條是可終止預清理的標記和持續的時間

4

2021-04-29T16:37:59.594+0800: 6.708: [GC (CMS Final Remark) [YG occupancy: 394027 K (629120 K)]2021-04-29T16:37:59.594+0800: 6.709: [Rescan (parallel) , 0.1164667 secs]2021-04-29T16:37:59.710+0800: 6.825: [weak refs processing, 0.0000352 secs]2021-0
4-29T16:37:59.710+0800: 6.825: [class unloading, 0.0041990 secs]2021-04-29T16:37:59.715+0800: 6.829: [scrub symbol table, 0.0038982 secs]2021-04-29T16:37:59.719+0800: 6.833: [scrub string table, 0.0005058 secs][1 CMS-remark: 0K(1398144K)] 394027K(2027264K), 0.1260089 secs] [Times: user=0.29 sys=0.00, real=0.12 secs]

這一段比較重要,我們一起來看一下,首先這個階段是CMS最後一個STW階段,任務是完成標記整個老年代的所有存活物件.他的內容如下:

  • 021-04-29T16:37:59.594+0800

    執行的時間

  • GC (CMS Final Remark)

    表明當前是最終的收集階段

  • [YG occupancy: 394027 K (629120 K)]

    年輕代的當前佔用的情況和容量

  • 2021-04-29T16:37:59.594+0800: 6.709: [Rescan (parallel , 0.1164667 secs]

    完成存活物件的標記工作

  • 2021-04-29T16:37:59.710+0800: 6.825: [weak refs processing, 0.0000352 secs]

    這個階段處理弱引用

  • 2021-04-29T16:37:59.710+0800: 6.825: [class unloading, 0.0041990 secs]

    解除安裝類所用的時間

  • 2021-04-29T16:37:59.715+0800: 6.829: [scrub symbol table, 0.0038982 secs]

    清理字串,後設資料之類的佔用

  • [1 CMS-remark: 0K(1398144K)] 394027K(2027264K), 0.1260089 secs] [Times: user=0.29 sys=0.00, real=0.12 secs]

    這個階段以後,老年代的佔用記憶體大小和容量(1398144),以及整個堆的大小和容量(2027264)

    以及所耗時間.

5

2021-04-29T16:37:59.720+0800: 6.835: [CMS-concurrent-sweep-start]
2021-04-29T16:37:59.720+0800: 6.835: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-04-29T16:37:59.720+0800: 6.835: [CMS-concurrent-reset-start]
2021-04-29T16:37:59.791+0800: 6.906: [CMS-concurrent-reset: 0.071/0.071 secs] [Times: user=0.07 sys=0.05, real=0.07 secs] 

  • 2021-04-29T16:37:59.720+0800: 6.835: [CMS-concurrent-sweep-start]
2021-04-29T16:37:59.720+0800: 6.835: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

    這兩句是說,開始清除垃圾物件,這個時候,程式不是STW狀態(stop the word),後面一句是耗時

  • 2021-04-29T16:37:59.720+0800: 6.835: [CMS-concurrent-reset-start]
2021-04-29T16:37:59.791+0800: 6.906: [CMS-concurrent-reset: 0.071/0.071 secs] [Times: user=0.07 sys=0.05, real=0.07 secs]

    這裡是說,重新設定CMS演算法內部的資料結構,準備下一個週期.也就是老年代清理完畢後的初始化.

OK,基本上到這裡以後,所有的內容應該都有說過了.

ParNew和CMS的日誌解析就到這裡了.下面是G1部分

3) G1 日誌分析

因為我這篇博文的所有資料都是來源於實際的生產環境,但是目前還沒有使用到G1,我也不想用本地的資料來驗證,因此先空再這裡,後面生產環境實際使用G1以後會更新.

7. 結語

其實現階段有了K8S容器化技術以後,基本上小中型公司的JVM一般是不用做什麼大的調整的.我文中所示的,也是我們目前生產環境K8S容器中的真實資料,技術的學習在於不斷的積累和驗證,關於JVM調優,這只是個開始,也不會結束.希望能記錄下來與君共勉.

其他日誌詳細資訊,可以參考一下來自Oracle官方的部落格.

https://blogs.oracle.com/poonam/understanding-cms-gc-logs CMS

https://blogs.oracle.com/poonam/understanding-g1-gc-logs G1

個人公眾號<橙耘自留地>日前已經開通,後續博主釋出的文章都會一併更新到公眾號,如有需要,自行查閱.

關於橙耘自留地,是我個人聚焦網際網路技術棧學習分享的一個平臺,創立之初是因為目前業內各種技術課程資料層次不齊,褒貶不一,有時候一門課花費高價買入,其實內含草包,有時偶爾低價得之,卻又大有乾貨.因此我會根據大家的意見和評價,選擇不同的技術棧去學習,一為提升我自己的技術,二為大家梳理出質量比較好的課程,以作參考.同時,相關的學習心得也會一併更新到部落格和公眾號.

qrcode_for_gh_c1462e34b232_344

相關文章