天天看點
傳回

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

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日志,如下:

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

日志的内容我們等下再詳細講解.接下來比如我們以上配置的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情況

列印結果如下:

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

其實

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]

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

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

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

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

可以看到,我簡化後,将日志劃分成了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工作在核心态所花費的時間
    詳細的解釋可以參考

    ***

    的文章

    在這裡,

    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的情況.下面對這段日志進行分析.

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

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

個人公衆号<橙耘自留地>日前已經開通,後續部落客釋出的文章都會一并更新到公衆号,如有需要,自行查閱.
關于橙耘自留地,是我個人聚焦網際網路技術棧學習分享的一個平台,創立之初是因為目前業内各種技術課程資料層次不齊,褒貶不一,有時候一門課花費高價買入,其實内含草包,有時偶爾低價得之,卻又大有幹貨.是以我會根據大家的意見和評價,選擇不同的技術棧去學習,一為提升我自己的技術,二為大家梳理出品質比較好的課程,以作參考.同時,相關的學習心得也會一并更新到部落格和公衆号.
jvmgc日志jvm
上一篇: python用matplotlib畫玫瑰_Python可視化：用Matplotlib畫個玫瑰圖
下一篇: html canvas抽獎,HTML5 Canvas圓盤抽獎應用（适用于Vue項目）