Java GC算法——日志解读与分析（GC参数基础配置分析）
Posted 砖业洋__
tags:
篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了Java GC算法——日志解读与分析（GC参数基础配置分析）相关的知识，希望对你有一定的参考价值。
可以先阅读前篇：Java GC算法背景原理与内存池划分，对于内存池的划分先有个概念后再来看各个部分的垃圾回收详情会更好
文章目录
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,<以上是关于Java GC算法——日志解读与分析（GC参数基础配置分析）的主要内容，如果未能解决你的问题，请参考以下文章
Java GC算法——日志解读与分析（GC参数基础配置分析）
Java GC算法——日志解读与分析（GC参数基础配置分析）
Java GC垃圾收集器的具体实现与日志案例分析(串行并行CMSG1)
Java GC垃圾收集器的具体实现与日志案例分析(串行并行CMSG1)
Java GC垃圾收集器的具体实现与日志案例分析(串行并行CMSG1)
Java 虚拟机原理垃圾回收算法 ( 设置 JVM 命令参数输出 GC 日志 | GC 日志输出示例 | GC 日志分析 )