1. 触发GC的示例代码
为了演示需要,代码如下:
import java.util.Random;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.LongAdder;
public class GCLogAnalysis {
private static Random random = new Random();
public static void main(String[] args) {
// 当前毫秒时间戳
long startMillis = System.currentTimeMillis();
// 持续运行毫秒数; 可根据需要进行修改
//
long timeoutMillis = TimeUnit.SECONDS.toMillis(1);
// 结束时间戳
long endMillis = startMillis + timeoutMillis;
LongAdder counter = new LongAdder();
System.out.println("正在执行...");
// 缓存一部分对象; 进入老年代
int cacheSize = 2000;
Object[] cachedGarbage = new Object[cacheSize];
// 在此时间范围内,持续循环
while (System.currentTimeMillis() < endMillis) {
// 生成垃圾对象
Object garbage = generateGarbage(100 * 1024);
counter.increment();
int randomIndex = random.nextInt(2 * cacheSize);
if (randomIndex < cacheSize) {
cachedGarbage[randomIndex] = garbage;
}
}
System.out.println("执行结束!共生成对象次数:" + counter.longValue());
}
// 生成对象
private static Object generateGarbage(int max) {
int randomSize = random.nextInt(max);
int type = randomSize % 4;
Object result = null;
switch (type) {
case 0:
result = new int[randomSize];
break;
case 1:
result = new byte[randomSize];
break;
case 2:
result = new double[randomSize];
break;
default:
StringBuilder builder = new StringBuilder();
String randomString = "randomString-Anything";
while (builder.length() < randomSize) {
builder.append(randomString);
builder.append(max);
builder.append(randomSize);
}
result = builder.toString();
break;
}
return result;
}
}
在 main
方法中,我们用一个数组来随机存放一部分生成的对象,这样可以模拟让部分对象晋升到老年代。
一般来说,Java
中的大对象主要就是各种各样的数组,比如开发中最常见的字符串,实际上 String
内部就是使用字符数组 char[]
来存储的。
2. 常见的GC日志参数
我这里使用JDK
命令行,可以使用 javac
工具来编译成class
文件,使用 java
命令来执行class
文件
JDK8
以上版本,java
和javac
命令可以合并成一个,java
命令编译和执行是一起的,执行.java
文件就可以出结果
因为我这里是JDK8
演示,所以就java
命令执行class
文件作为示范。
2.1 输出日志详情
加上启动参数 -XX:+PrintGCDetails
,打印GC
日志详情,再次执行示例
D:\javaPractice\javaPracticeTest\out\production\javaPracticeTest>java -XX:+PrintGCDetails GCLogAnalysis
执行后可以看到GC
的情况如下,后面我们一步步分析:
[GC (Allocation Failure) [PSYoungGen: 65024K->10735K(75776K)] 65024K->23220K(249344K), 0.0046033 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC (Allocation Failure) [PSYoungGen: 75759K->10745K(140800K)] 88244K->45325K(314368K), 0.0065771 secs] [Times: user=0.03 sys=0.03, real=0.01 secs]
[GC (Allocation Failure) [PSYoungGen: 140793K->10747K(140800K)] 175373K->84823K(314368K), 0.0094744 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [PSYoungGen: 140795K->10742K(270848K)] 214871K->125146K(444416K), 0.0097900 secs] [Times: user=0.03 sys=0.03, real=0.01 secs]
[GC (Allocation Failure) [PSYoungGen: 270838K->10746K(270848K)] 385242K->200111K(460800K), 0.0159145 secs] [Times: user=0.03 sys=0.03, real=0.02 secs]
[Full GC (Ergonomics) [PSYoungGen: 10746K->0K(270848K)] [ParOldGen: 189365K->166267K(326656K)] 200111K->166267K(597504K), [Metaspace: 2608K->2608K(1056768K)], 0.021
6138 secs] [Times: user=0.11 sys=0.01, real=0.02 secs]
[GC (Allocation Failure) [PSYoungGen: 260096K->83528K(540672K)] 426363K->249795K(867328K), 0.0181100 secs] [Times: user=0.05 sys=0.02, real=0.02 secs]
[GC (Allocation Failure) [PSYoungGen: 540232K->102898K(591360K)] 706499K->357559K(918016K), 0.0314269 secs] [Times: user=0.09 sys=0.03, real=0.03 secs]
[Full GC (Ergonomics) [PSYoungGen: 102898K->0K(591360K)] [ParOldGen: 254661K->278543K(483840K)] 357559K->278543K(1075200K), [Metaspace: 2608K->2608K(1056768K)], 0.0
355931 secs] [Times: user=0.13 sys=0.01, real=0.04 secs]
[GC (Allocation Failure) [PSYoungGen: 488448K->140935K(949760K)] 766991K->419478K(1433600K), 0.0328920 secs] [Times: user=0.03 sys=0.08, real=0.03 secs]
[GC (Allocation Failure) [PSYoungGen: 925831K->183280K(968192K)] 1204374K->545835K(1452032K), 0.0670426 secs] [Times: user=0.05 sys=0.11, real=0.07 secs]
[GC (Allocation Failure) [PSYoungGen: 968176K->247283K(1060352K)] 1330731K->655186K(1544192K), 0.0844278 secs] [Times: user=0.05 sys=0.11, real=0.08 secs]
[Full GC (Ergonomics) [PSYoungGen: 247283K->0K(1060352K)] [ParOldGen: 407903K->374258K(601600K)] 655186K->374258K(1661952K), [Metaspace: 2608K->2608K(1056768K)], 0.
0570233 secs] [Times: user=0.13 sys=0.00, real=0.06 secs]
执?结束!共生成对象次数:12932
Heap
PSYoungGen total 1060352K, used 32874K [0x000000076b600000, 0x00000007c0000000, 0x00000007c0000000)
eden space 813056K, 4% used [0x000000076b600000,0x000000076d61aae8,0x000000079d000000)
from space 247296K, 0% used [0x00000007b0e80000,0x00000007b0e80000,0x00000007c0000000)
to space 286720K, 0% used [0x000000079d000000,0x000000079d000000,0x00000007ae800000)
ParOldGen total 601600K, used 374258K [0x00000006c2200000, 0x00000006e6d80000, 0x000000076b600000)
object space 601600K, 62% used [0x00000006c2200000,0x00000006d8f7cb40,0x00000006e6d80000)
Metaspace used 2615K, capacity 4486K, committed 4864K, reserved 1056768K
class space used 288K, capacity 386K, committed 512K, reserved 1048576K
可以看到,使用启动参数 -XX:+PrintGCDetails
,发生GC
时会输出相关的GC
日志。
这个参数的格式为:
-XX:+
,这个加号+
是一个布尔值开关,关闭就是减号-
来分析一下日志:
[GC (Allocation Failure) [PSYoungGen: 65024K->10735K(75776K)] 65024K->23220K(249344K), 0.0046033 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC (Allocation Failure)]
表示GC
的原因是内存分配失败[PSYoungGen: 65024K->10735K(75776K)]
表示GC
前年轻代占用内存65024K
,GC
后年轻代占用内存为10735K
,年轻代总内存75776K
65024K->23220K(249344K)
表示GC
前占用的堆内存是65024K
,GC
后占用的堆内存为23220K
,此时总堆内存为249344K
细心的朋友可以观察到,每次GC后,年轻代、老年代和堆内存容量都在扩大,那是因为jvm有自适应参数,可以关掉-XX:-UseAdaptiveSizePolicy
,这样容量就是一样的了
java -XX:+PrintGCDetails -XX:-UseAdaptiveSizePolicy GCLogAnalysis
如果大家看了我前一篇文章:Java GC算法背景原理与内存池划分
我在里面提到“如果对象经历了一定的GC
次数后仍然存活,那么它们就会挪到老年代。比如默认情况下是15
次”,结果我们观察前面两次Full GC
日志发现,GC
不到15
次,结果年轻代就挪到老年代了
[Full GC (Ergonomics) [PSYoungGen: 10746K->0K(270848K)] [ParOldGen: 189365K->166267K(326656K)] 200111K->166267K(597504K), [Metaspace: 2608K->2608K(1056768K)], 0.021
6138 secs] [Times: user=0.11 sys=0.01, real=0.02 secs]
......
[Full GC (Ergonomics) [PSYoungGen: 102898K->0K(591360K)] [ParOldGen: 254661K->278543K(483840K)] 357559K->278543K(1075200K), [Metaspace: 2608K->2608K(1056768K)], 0.0
355931 secs] [Times: user=0.13 sys=0.01, real=0.04 secs]
......
第一次Full GC
根据日志还看不出是否年轻代对象有移动到老年代,第二次就看得出了,ParOldGen: 254661K->278543K(483840K)
,经过Full GC
后,老年代占用的内存居然还增加了,这就是年轻代对象提升到老年代的结果。
从上面日志可以计算出,第二次Full GC
时,年轻代对象全部晋升到老年代。
为什么GC
不到15
次就提升了呢?15
是最大值,到了15
次是强制提升到老年代,但是不代表GC
小于15
次时,年轻代对象就不提升到老年代。如果存活区S0
和S1
空间不足以存放这些年轻代的对象,提升到老年代的动作会更早的进行。
在程序执行完成后、JVM
关闭前,还会输出各个内存池的使用情况, 从最后面的输出中可以看到。 下面我们来简单解读上面输出的堆内存信息。
Heap 堆内存使用情况
Heap
PSYoungGen total 1060352K, used 32874K [0x000000076b600000, 0x00000007c0000000, 0x00000007c0000000)
eden space 813056K, 4% used [0x000000076b600000,0x000000076d61aae8,0x000000079d000000)
from space 247296K, 0% used [0x00000007b0e80000,0x00000007b0e80000,0x00000007c0000000)
to space 286720K, 0% used [0x000000079d000000,0x000000079d000000,0x00000007ae800000)
PSYoungGen
,年轻代总计1060352K
,使用量32874K
,后面的方括号中是内存地址信息- 其中
eden space
占用了813056K
, 其中4% used
- 其中
from space
占用了247296K
, 其中0% used
- 其中
to space
占用了286720K
, 其中0% used
ParOldGen total 601600K, used 374258K [0x00000006c2200000, 0x00000006e6d80000, 0x000000076b600000)
object space 601600K, 62% used [0x00000006c2200000,0x00000006d8f7cb40,0x00000006e6d80000)
ParOldGen
, 老年代总计total 601600K
, 使用量374258K
- 其中
object space
占用了601600K
, 其中62% used
- 其中
Metaspace used 2615K, capacity 4486K, committed 4864K, reserved 1056768K
class space used 288K, capacity 386K, committed 512K, reserved 1048576K
Metaspace
, 元数据区总计使用了2615K
, 容量是4486K
,JVM
保证可用的大小是4864K
, 保留空间1056768K
- 其中
class space
使用了288K
,capacity 386K
- 其中
2.2 指定输出GC日志文件
我们在前面的基础上, 加上启动参数 -Xloggc:gc.demo.log
java -XX:+PrintGCDetails -Xloggc:gc.demo.log GCLogAnalysis
提示: 从
JDK8
开始,支持使用%p
,%t
等占位符来指定GC
输出文件。分别表示进程pid
和启动时间 戳。例如:-Xloggc:gc.%p.log
;-Xloggc:gc-%t.log
; 在某些情况下,将每次JVM
执行的GC
日志输出到不同的文件可以方便排查问题。 如果业务访问量大,导致GC
日志文件太大,可以开启GC
日志轮换,分割成多个文件,可以参考: https://blog.gceasy.io/2016/11/15/rotating-gc-log-files
Java HotSpot(TM) 64-Bit Server VM (25.212-b10) for windows-amd64 JRE (1.8.0_212-b10), built on Apr 1 2019 22:50:23 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16633820k(5272488k free), swap 24466864k(4759596k free)
CommandLine flags: -XX:InitialHeapSize=266141120 -XX:MaxHeapSize=4258257920 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC
0.119: [GC (Allocation Failure) [PSYoungGen: 64788K->10731K(75776K)] 64788K->22484K(249344K), 0.0046170 secs] [Times: user=0.00 sys=0.02, real=0.00 secs]
0.137: [GC (Allocation Failure) [PSYoungGen: 75705K->10734K(140800K)] 87457K->40418K(314368K), 0.0059229 secs] [Times: user=0.02 sys=0.03, real=0.01 secs]
0.177: [GC (Allocation Failure) [PSYoungGen: 140777K->10739K(140800K)] 170461K->81464K(314368K), 0.0095714 secs] [Times: user=0.00 sys=0.01, real=0.01 secs]
0.203: [GC (Allocation Failure) [PSYoungGen: 140787K->10742K(270848K)] 211512K->119655K(444416K), 0.0083573 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
0.275: [GC (Allocation Failure) [PSYoungGen: 270838K->10735K(270848K)] 379751K->197582K(457728K), 0.0161735 secs] [Times: user=0.02 sys=0.03, real=0.02 secs]
0.291: [Full GC (Ergonomics) [PSYoungGen: 10735K->0K(270848K)] [ParOldGen: 186846K->168343K(332288K)] 197582K->168343K(603136K), [Metaspace: 2608K->2608K(1056768K)], 0.0242948 secs] [Times: user=0.13 sys=0.00, real=0.02 secs]
0.353: [GC (Allocation Failure) [PSYoungGen: 260091K->91088K(540160K)] 428435K->259431K(872448K), 0.0151566 secs] [Times: user=0.02 sys=0.05, real=0.01 secs]
0.485: [GC (Allocation Failure) [PSYoungGen: 540112K->109043K(593920K)] 708455K->361812K(926208K), 0.0424333 secs] [Times: user=0.02 sys=0.11, real=0.04 secs]
0.528: [Full GC (Ergonomics) [PSYoungGen: 109043K->0K(593920K)] [ParOldGen: 252769K->275830K(484352K)] 361812K->275830K(1078272K), [Metaspace: 2608K->2608K(1056768K)], 0.0449918 secs] [Times: user=0.11 sys=0.02, real=0.04 secs]
0.660: [GC (Allocation Failure) [PSYoungGen: 484864K->139121K(934400K)] 760694K->414951K(1418752K), 0.0349132 secs] [Times: user=0.03 sys=0.06, real=0.04 secs]
0.829: [GC (Allocation Failure) [PSYoungGen: 902513K->187385K(950784K)] 1178343K->544621K(1435136K), 0.0657464 secs] [Times: user=0.09 sys=0.11, real=0.06 secs]
0.991: [GC (Allocation Failure) [PSYoungGen: 950777K->251378K(1020416K)] 1308013K->654723K(1504768K), 0.0679324 secs] [Times: user=0.08 sys=0.13, real=0.07 secs]
1.059: [Full GC (Ergonomics) [PSYoungGen: 251378K->0K(1020416K)] [ParOldGen: 403344K->371836K(604672K)] 654723K->371836K(1625088K), [Metaspace: 2608K->2608K(1056768K)], 0.0540675 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]
Heap
PSYoungGen total 1020416K, used 30969K [0x000000076b600000, 0x00000007c0000000, 0x00000007c0000000)
eden space 769024K, 4% used [0x000000076b600000,0x000000076d43e698,0x000000079a500000)
from space 251392K, 0% used [0x00000007b0a80000,0x00000007b0a80000,0x00000007c0000000)
to space 308736K, 0% used [0x000000079a500000,0x000000079a500000,0x00000007ad280000)
ParOldGen total 604672K, used 371836K [0x00000006c2200000, 0x00000006e7080000, 0x000000076b600000)
object space 604672K, 61% used [0x00000006c2200000,0x00000006d8d1f230,0x00000006e7080000)
Metaspace used 2615K, capacity 4486K, committed 4864K, reserved 1056768K
class space used 288K, capacity 386K, committed 512K, reserved 1048576K
我们可以发现, 加上 -Xloggc:
参数之后, GC
日志信息输出到日志文件中
文件里最前面是JVM
相关信息, 比如内存页面大小, 物理内存大小, 剩余内存等信息
然后是 CommandLine flags
这部分内容。 在分析GC
日志文件时,命令行参数也是一项重要的参考。 因为可能你拿到了日志文件,却不知道线上的配置,日志文件中打印了这个信息,能有效减少分析排查时间。比如你可以看到用了哪些GC
日志参数
指定 -Xloggc:
参数,自动加上了 -XX:+PrintGCTimeStamps
配置,观察GC
日志文件可以看到, 每一行前面多了一个时间戳(如 0.119:
),表示JVM
启动后经过的时间(单位秒)
细心的同学还可以发现,JDK8
默认使用的垃圾收集器参数: -XX:+UseParallelGC
2.3 打印GC事件发生的日期和时间
在前面的基础上,加上启动参数 -XX:+PrintGCDateStamps
,再次执行
java -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:gc.demo.log GCLogAnalysis
加上 -XX:+PrintGCDateStamps
参数之后,GC
日志每一行前面,都打印了GC
发生时的具体时间。如 2021-12-16T15:52:22.926+0800
,表示的是: 东8
区时间2021
年12
月16
日15:52:22
秒.926
毫秒
2.4 指定堆内存的大小
从前面的示例中可以看到输出GC
日志文件时有的 CommandLine flags
信息。
即使我们没有指定堆内存,JVM
在启动时也会自动算出一个默认值出来。 例如: -XX:InitialHeapSize=266141120
-XX:MaxHeapSize=4258257920
等价于 -Xms256m
-Xmx4g
配置。
我们现在继续增加参数,这次加上启动参数 -Xms512m
-Xmx512m
,再次执行
java -Xms512m -Xmx512m -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:gc.demo.log GCLogAnalysis
此时堆内存的初始值和最大值都是512MB
。具体的参数可根据实际需要配置,我们为了演示,使用了一个较小的堆内存配置,实际肯定比这大
2.5 指定垃圾收集器
一般来说,使用JDK8
时我们可以使用以下几种垃圾收集器:
-XX:+UseSerialGC
-XX:+UseParallelGC
-XX:+UseParallelGC -XX:+UseParallelOldGC
-XX:+UseConcMarkSweepGC
-XX:+UseConcMarkSweepGC -XX:+UseParNewGC
-XX:+UseG1GC
- 使用串行垃圾收集器:
-XX:+UseSerialGC
- 使用并行垃圾收集器:
-XX:+UseParallelGC
和-XX:+UseParallelGC -XX:+UseParallelOldGC
是等价的, 可以通过GC
日志文件中的flags
看出来。 - 用
CMS
垃圾收集器:-XX:+UseConcMarkSweepGC
和-XX:+UseParNewGC -XX:+UseConcMarkSweepGC
是等价的。 但如果只指定-XX:+UseParNewGC
参数则老年代GC
会 使用SerialGC
。使用CMS
时,命令行参数中会自动计算出年轻代、老年代的初始值和最大值,以及最大晋升阈值等信息(例如-XX:MaxNewSize=178958336 -XX:NewSize=178958336 -XX:OldSize=357912576
)。 - 使用
G1
垃圾收集器:-XX:+UseG1GC
。原则上不能指定G1
垃圾收集器的年轻代大小,否则不仅是画蛇添足,更是自废武功了。因为G1
的回收方式是小批量划定区块(region
)进行,可能一次普通GC
中 既有年轻代又有老年代,可能某个区块一会是老年代,一会又变成年轻代了。
如果使用不支持的
GC
组合,会启动失败,报fatal
错误。
2.6 其他参数
JVM
里还有一些GC
日志相关的参数, 例如:
-XX:+PrintGCApplicationStoppedTime
可以输出每次GC
的持续时间和程序暂停时间;-XX:+PrintReferenceGC
输出GC
清理了多少引用类型。
大部分情况下,配置
GC
参数并不是越多越好。原则上只配置最重要的几个参数即可,其他的都保持默认值。
3. GC事件的类型
一般来说,垃圾收集事件(Garbage Collection events
)可以分为三种类型:
Minor GC
(小型GC
)Major GC
(大型GC
)Full GC
(完全GC
)
虽然 Minor GC
, Major GC
和 Full GC
这几个词汇到处都在用,但官方并没有给出标准的定义。 这些术语出现在官方的各种分析工具和垃圾收集日志中,并不是很统一。官方的文档和工具之间也常常混淆,这些混淆甚至根植于标准的JVM
工具中。
MinorGC
称为 小型GC
,还是 次要GC
更合理呢? 辨析:在大部分情况下, 发生在年轻代的Minor GC
次数更多, 有些文章将次数更多的GC
称为次要GC
明显是不太合理的。
在这里
- 将
Minor GC
翻译为小型GC
,而不是次要GC
;- 将
Major GC
翻译为大型GC
, 而不是主要GC
;- 将
Full GC
翻译为完全GC
,有时候也直接称为Full GC
。
3.1 Minor GC(小型GC)
收集年轻代内存的GC
事件称为 Minor GC
。关于 Minor GC
事件, 我们需要了解一些相关的内容:
- 当
JVM
无法为新对象分配内存空间时就会触发Minor GC
( 一般就是Eden
区用满了)。 如果对象的分配速率很快, 那么Minor GC
的次数也就会很多,频率也就会很快。 Minor GC
事件不处理老年代, 所以会把所有从老年代指向年轻代的引用都当做GC Root
。从年 轻代指向老年代的引用则在标记阶段被忽略。- 与我们一般的认知相反,
Minor GC
每次都会引起STW
停顿(stop-the-world
), 挂起所有的应用线程。 对大部分应用程序来说,Minor GC
的暂停时间可以忽略不计,因为Eden
区里面的对象大部分都是垃圾,也不怎么复制到存活区/老年代。 但如果不符合这种情况,那么很多新创建的对象就不能被GC
清理,Minor GC
的停顿时间就会增大,就会产生比较明显的GC
性能影响。
简单定义:
Minor GC
清理的是年轻代,又或者说Minor GC
就是 年轻代GC
(Young GC
,简称YGC
)
3.2 Major GC vs. Full GC
值得一提的是,这几个术语都没有正式的定义--无论是在JVM
规范中还是在GC
论文中。
我们知道,除了 Minor GC
外,另外两种GC
事件则是:
Major GC
(大型GC
) :清理老年代空间(Old Space
)的GC
事件。Full GC
(完全GC
) :清理整个堆内存空间的GC
事件,包括年轻代空间和老年代空间。其实
Major GC
和Full GC
有时候并不能很好地区分。更复杂的情况是, 很多Major GC
是由Minor GC
触发的,所以很多情况下这两者是不可分离的。另外,像
G1
这种垃圾收集算法,是每次找一小部分区域来进行清理,这部分区域中可能有一部分是年轻代,另一部分区域属于老年代。所以我们不要太纠结具体是叫
Major GC
呢还是叫Full GC
,它们一般都会造成单次较长时间的STW
暂停。所以我们需要关注的是:某次GC
事件,是暂停了所有线程、进而对系统造成了性能影响呢,还是与其他业务线程并发执行、暂停时间几乎可以忽略不计。
后续文章会写指定各个垃圾回收器时的GC日志,请大家继续关注
欢迎一键三连~
有问题请留言,大家一起探讨学习
----------------------Talk is cheap, show me the code-----------------------