java8 GC日志分析

我不是女神ヾ 2022-05-10 12:24 301阅读 0赞

### 文章目录 ###

*  前言
 *  背景：
 *  jmap查看信息：
 *  GC运行情况：
 *  启动参数：
 *  查看GC日志
 *   *   *  设置tomcat
         *  查看日志
         *  minor GC 日志分析
         *  Full GC 日志分析
 *  参考文档

# 前言 #

最近学习分析了一下java8的GC日志，顺便记录下来，忘性太大了

# 背景： #

java version "1.8.0_144"
    Java(TM) SE Runtime Environment (build 1.8.0_144-b01)
    Java HotSpot(TM) 64-Bit Server VM (build 25.144-b01, mixed mode)

# jmap查看信息： #

jmap -heap 56343

Attaching to process ID 56343, please wait...
    Debugger attached successfully.
    Server compiler detected.
    JVM version is 25.144-b01
    
    using thread-local object allocation.
    Parallel GC with 8 thread(s)
    
    Heap Configuration:
       MinHeapFreeRatio         = 0
       MaxHeapFreeRatio         = 100
       MaxHeapSize              = 4294967296 (4096.0MB)
       NewSize                  = 89128960 (85.0MB)
       MaxNewSize               = 1431306240 (1365.0MB)
       OldSize                  = 179306496 (171.0MB)
       NewRatio                 = 2
       SurvivorRatio            = 8
       MetaspaceSize            = 21807104 (20.796875MB)
       CompressedClassSpaceSize = 1073741824 (1024.0MB)
       MaxMetaspaceSize         = 17592186044415 MB
       G1HeapRegionSize         = 0 (0.0MB)
    
    Heap Usage:
    PS Young Generation
    Eden Space:
       capacity = 1286078464 (1226.5MB)
       used     = 569220648 (542.8511123657227MB)
       free     = 716857816 (683.6488876342773MB)
       44.26018038040951% used
    From Space:
       capacity = 69206016 (66.0MB)
       used     = 25521552 (24.339248657226562MB)
       free     = 43684464 (41.66075134277344MB)
       36.877649480646305% used
    To Space:
       capacity = 66060288 (63.0MB)
       used     = 0 (0.0MB)
       free     = 66060288 (63.0MB)
       0.0% used
    PS Old Generation
       capacity = 163577856 (156.0MB)
       used     = 55992088 (53.398216247558594MB)
       free     = 107585768 (102.6017837524414MB)
       34.22962579971705% used
    
    29765 interned Strings occupying 3248952 bytes.

**MaxHeapFreeRatio**: GC后如果发现空闲堆内存占到整个预估堆内存的N%(百分比)，则收缩堆内存的预估最大值, 预估堆内存是堆大小动态调控的重要选项之一. 堆内存预估最大值一定小于或等于固定最大值(-Xmx指定的数值). 前者会根据使用情况动态调大或缩小, 以提高GC回收的效率MinHeapFreeRatio: GC后如果发现空闲堆内存占到整个预估堆内存的N%(百分比), 则放大堆内存的预估最大值

**MaxHeapSize**: 即-Xmx, 堆内存大小的上限

**InitialHeapSize**: 即-Xms, 堆内存大小的初始值

**NewSize**: 新生代预估堆内存占用的默认值

**MaxNewSize**: 新生代占整个堆内存的最大值

**OldSize**: 老年代的默认大小, default size of the tenured generation

**NewRatio**: 老年代对比新生代的空间大小, 比如2代表老年代空间是新生代的两倍大小. The ratio of old generation to young generation.

**SurvivorRatio**: Eden/Survivor的值. 这个值的说明, 很多网上转载的都是错的. 8表示Survivor:Eden=1:8, 因为survivor区有2个, 所以Eden的占比为8/10. Ratio of eden/survivor space size. -XX:SurvivorRatio=6 sets the ratio between each survivor space and eden to be 1:6, each survivor space will be one eighth of the young generation.

**MetaspaceSize**: 分配给类元数据空间的初始大小(Oracle逻辑存储上的初始高水位，the initial high-water-mark ). 此值为估计值. MetaspaceSize设置得过大会延长垃圾回收时间. 垃圾回收过后, 引起下一次垃圾回收的类元数据空间的大小可能会变大

**MaxMetaspaceSize**: 是分配给类元数据空间的最大值, 超过此值就会触发Full GC. 此值仅受限于系统内存的大小, JVM会动态地改变此值

**CompressedClassSpaceSize**: 类指针压缩空间大小, 默认为1G

**G1HeapRegionSize**: G1区块的大小, 取值为1M至32M. 其取值是要根据最小Heap大小划分出2048个区块. With G1 the Java heap is subdivided into uniformly sized regions. This sets the size of the individual sub-divisions. The default value of this parameter is determined ergonomically based upon heap size. The minimum value is 1Mb and the maximum value is 32Mb. Sets the size of a G1 region. The value will be a power of two and can range from 1MB to 32MB. The goal is to have around 2048 regions based on the minimum Java heap size.

# GC运行情况： #

jstat gcutil -pid

S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT   
    0.00  36.88  59.47  34.23  97.89  96.65     15    0.398     3    0.269    0.667

S0: 新生代中Survivor space 0区已使用空间的百分比

S1:新生代中Survivor space 1区已使用空间的百分比

E: Eden已使用空间的百分比

O:Old已使用空间的百分比

M：metaspace使用百分比

CCS：类指针压缩空间使用率 Compressed class space utilization as a percentage.

YGC：从应用程序启动到当前，发生Yang GC 的次数

YGCT：从应用程序启动到当前，Yang GC所用的时间【单位秒】

FGC：从应用程序启动到当前，发生Full GC的次数

FGCT：从应用程序启动到当前，Full GC所用的时间

GCT：从应用程序启动到当前，用于垃圾回收的总时间【单位秒】

# 启动参数： #

我的本地项目启动参数：

jinfo -flags 56343
    
    -XX:CICompilerCount=4 -- 最大并行编译数
    -XX:InitialHeapSize=268435456  -- 初始化堆大小
    -XX:+ManagementServer --
    -XX:MaxHeapSize=4294967296 --最大堆大小
    -XX:MaxNewSize=1431306240 --新生代最大大小
    -XX:MinHeapDeltaBytes=524288 --为了防止频繁扩展内存代空间,每次扩展内存代时都有一个最小值_min_heap_delta_bytes,由JVM参数MinHeapDeltaBytes决定,其默认值为128KB
    -XX:NewSize=89128960 --设置年轻代的大小
    -XX:OldSize=179306496 --老年代的大小
    -XX:+UseCompressedClassPointers --使用-XX:+UseCompressedClassPointers选项来压缩类指针
        --对象中指向类元数据的指针会被压缩成32位
        --类指针压缩空间会有一个基地址
    -XX:+UseCompressedOops --压缩对象指针
        --"oops"指的是普通对象指针("ordinary" object pointers)。
        --Java堆中对象指针会被压缩成32位。
        --使用堆基地址（如果堆在低26G内存中的话，基地址为0）
    -XX:+UseFastUnorderedTimeStamps 
    -XX:+UseParallelGC  --使用 Parallel收集器

# 查看GC日志 #

### 设置tomcat ###

vim /Users/liyi/myapp/apache-tomcat-8.5.23/bin/catalina.sh

添加

JAVA_OPTS="-server -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:/Users/liyi/myapp/apache-tomcat-8.5.23/logs/gc.$$.log"

到文件最前面。

### 查看日志 ###

启动tomcat  
查看logs/gc.$$.log

1.067: [GC (Allocation Failure) [PSYoungGen: 65536K->10748K(76288K)] 65536K->14605K(251392K), 0.0133509 secs] [Times: user=0.04 sys=0.01, real=0.01 secs] 
    1.443: [GC (Allocation Failure) [PSYoungGen: 76284K->10744K(141824K)] 80141K->18577K(316928K), 0.0126569 secs] [Times: user=0.04 sys=0.02, real=0.02 secs] 
    1.772: [GC (Allocation Failure) [PSYoungGen: 141816K->10746K(141824K)] 149649K->34101K(316928K), 0.0214159 secs] [Times: user=0.06 sys=0.01, real=0.02 secs] 
    2.081: [GC (Allocation Failure) [PSYoungGen: 141818K->10738K(272896K)] 165173K->49254K(448000K), 0.0228556 secs] [Times: user=0.10 sys=0.01, real=0.02 secs] 
    2.775: [GC (Allocation Failure) [PSYoungGen: 272882K->10739K(272896K)] 311398K->78908K(448000K), 0.0343582 secs] [Times: user=0.15 sys=0.02, real=0.03 secs] 
    3.378: [GC (Allocation Failure) [PSYoungGen: 272883K->38222K(561152K)] 341052K->106399K(736256K), 0.0285881 secs] [Times: user=0.09 sys=0.02, real=0.03 secs] 
    4.638: [GC (Allocation Failure) [PSYoungGen: 557390K->47073K(566272K)] 625567K->137810K(741376K), 0.0543765 secs] [Times: user=0.14 sys=0.04, real=0.05 secs] 
    5.703: [GC (Allocation Failure) [PSYoungGen: 566241K->66033K(1090560K)] 656978K->163980K(1265664K), 0.0603416 secs] [Times: user=0.09 sys=0.04, real=0.06 secs] 
    26.672: [GC (Metadata GC Threshold) [PSYoungGen: 462923K->25009K(1104384K)] 560870K->123676K(1279488K), 0.0240012 secs] [Times: user=0.04 sys=0.02, real=0.02 secs] 
    26.696: [Full GC (Metadata GC Threshold) [PSYoungGen: 25009K->0K(1104384K)] [ParOldGen: 98666K->33427K(135168K)] 123676K->33427K(1239552K), [Metaspace: 20826K->20826K(1069056K)], 0.0433701 secs] [Times: user=0.17 sys=0.00, real=0.05 secs] 
     56.355: [GC (Metadata GC Threshold) [PSYoungGen: 855695K->50537K(1317376K)] 889123K->83973K(1452544K), 0.0683987 secs] [Times: user=0.15 sys=0.03, real=0.07 secs] 
    56.423: [Full GC (Metadata GC Threshold) [PSYoungGen: 50537K->0K(1317376K)] [ParOldGen: 33435K->62082K(167936K)] 83973K->62082K(1485312K), [Metaspace: 34475K->34475K(1081344K)], 0.0678678 secs] [Times: user=0.30 sys=0.00, real=0.07 secs] 
    77.226: [GC (Metadata GC Threshold) [PSYoungGen: 927352K->29880K(1270272K)] 989434K->91971K(1438208K), 0.0282360 secs] [Times: user=0.08 sys=0.01, real=0.03 secs] 
    77.255: [Full GC (Metadata GC Threshold) [PSYoungGen: 29880K->0K(1270272K)] [ParOldGen: 62090K->54796K(167936K)] 91971K->54796K(1438208K), [Metaspace: 57953K->57953K(1101824K)], 0.1936572 secs] [Times: user=0.55 sys=0.02, real=0.19 secs] 
    379.100: [GC (Allocation Failure) [PSYoungGen: 1240064K->30296K(1319936K)] 1294860K->85100K(1487872K), 0.0177720 secs] [Times: user=0.08 sys=0.01, real=0.02 secs]

### minor GC 日志分析 ###

（第一条）：  
1.067: \[GC (Allocation Failure) \[PSYoungGen: 65536K->10748K(76288K)\] 65536K->14605K(251392K), 0.0133509 secs\] \[Times: user=0.04 sys=0.01, real=0.01 secs\]

!\[avatar\]\[youngGCpng\]  
![在这里插入图片描述][70]

### Full GC 日志分析 ###

（Metaspace不够用引发fullGC）：  
26.696: \[Full GC (Metadata GC Threshold) \[PSYoungGen: 25009K->0K(1104384K)\] \[ParOldGen: 98666K->33427K(135168K)\] 123676K->33427K(1239552K), \[Metaspace: 20826K->20826K(1069056K)\], 0.0433701 secs\] \[Times: user=0.17 sys=0.00, real=0.05 secs\]

!\[avatar\]\[fullGCpng\]  
![在这里插入图片描述][70 1]  
关于Times解释： [GC 时间 —— USER, SYS, REAL？][GC _ _ USER_ SYS_ REAL]

引发GC的原因：metaspace区使用内存达到MetaspaceSize设置的值，XX:MetaspaceSize是有一个默认值的：21M

fullGC原因有很多种，上面只是其中一种，而且所用的收集器不一样，日志也会不一样。  
扩展阅读：[GC之详解CMS收集过程和日志分析][GC_CMS]

# 参考文档 #

*  [https://blog.csdn.net/yxc135/article/details/12137663][https_blog.csdn.net_yxc135_article_details_12137663]
 *  [https://blog.csdn.net/yjl33/article/details/78890363][https_blog.csdn.net_yjl33_article_details_78890363]
 *  [https://blog.csdn.net/liubenlong007/article/details/78143285][https_blog.csdn.net_liubenlong007_article_details_78143285]

[70]: /images/20220510/e88af7f9335f430ca7df8d9b489227c8.png
[70 1]: /images/20220510/50315943b8dd4634af0bb99d2b283295.png
[GC _ _ USER_ SYS_ REAL]: https://my.oschina.net/dabird/blog/714569
[GC_CMS]: http://www.cnblogs.com/zhangxiaoguang/p/5792468.html
[https_blog.csdn.net_yxc135_article_details_12137663]: https://blog.csdn.net/yxc135/article/details/12137663
[https_blog.csdn.net_yjl33_article_details_78890363]: https://blog.csdn.net/yjl33/article/details/78890363
[https_blog.csdn.net_liubenlong007_article_details_78143285]: https://blog.csdn.net/liubenlong007/article/details/78143285