GC日志详情
Java HotSpot(TM) 64-Bit Server VM (25.25-b02) for linux-amd64 JRE (1.8.0_25-b17), built on Sep 17 2014 17:32:11 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 32779816k(1555852k free), swap 0k(0k free)
CommandLine flags: -XX:InitialHeapSize=4294967296 -XX:MaxHeapSize=4294967296 -XX:+PrintClassHistogram -XX:+PrintGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:ThreadStackSize=512 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC
2021-06-22T16:04:47.326+0800: 2.223: Total time for which application threads were stopped: 0.0002528 seconds
2021-06-22T16:04:47.352+0800: 2.249: Total time for which application threads were stopped: 0.0001974 seconds
{Heap before GC invocations=1 (full 0):
PSYoungGen total 1223168K, used 796938K [0x000000076ab00000, 0x00000007c0000000, 0x00000007c0000000)
eden space 1048576K, 76% used [0x000000076ab00000,0x000000079b542b78,0x00000007aab00000)
from space 174592K, 0% used [0x00000007b5580000,0x00000007b5580000,0x00000007c0000000)
to space 174592K, 0% used [0x00000007aab00000,0x00000007aab00000,0x00000007b5580000)
ParOldGen total 2796544K, used 0K [0x00000006c0000000, 0x000000076ab00000, 0x000000076ab00000)
object space 2796544K, 0% used [0x00000006c0000000,0x00000006c0000000,0x000000076ab00000)
Metaspace used 20827K, capacity 21114K, committed 21248K, reserved 1067008K
class space used 2916K, capacity 3027K, committed 3072K, reserved 1048576K
2021-06-22T16:04:51.184+0800: 6.081: [GC (Metadata GC Threshold)
Desired survivor size 178782208 bytes, new threshold 7 (max 15)
[PSYoungGen: 796938K->23321K(1223168K)] 796938K->23337K(4019712K), 0.0630982 secs] [Times: user=0.06 sys=0.01, real=0.06 secs]
Heap after GC invocations=1 (full 0):
PSYoungGen total 1223168K, used 23321K [0x000000076ab00000, 0x00000007c0000000, 0x00000007c0000000)
eden space 1048576K, 0% used [0x000000076ab00000,0x000000076ab00000,0x00000007aab00000)
from space 174592K, 13% used [0x00000007aab00000,0x00000007ac1c6498,0x00000007b5580000)
to space 174592K, 0% used [0x00000007b5580000,0x00000007b5580000,0x00000007c0000000)
ParOldGen total 2796544K, used 16K [0x00000006c0000000, 0x000000076ab00000, 0x000000076ab00000)
object space 2796544K, 0% used [0x00000006c0000000,0x00000006c0004000,0x000000076ab00000)
Metaspace used 20827K, capacity 21114K, committed 21248K, reserved 1067008K
class space used 2916K, capacity 3027K, committed 3072K, reserved 1048576K
}
{Heap before GC invocations=2 (full 1):
PSYoungGen total 1223168K, used 23321K [0x000000076ab00000, 0x00000007c0000000, 0x00000007c0000000)
eden space 1048576K, 0% used [0x000000076ab00000,0x000000076ab00000,0x00000007aab00000)
from space 174592K, 13% used [0x00000007aab00000,0x00000007ac1c6498,0x00000007b5580000)
to space 174592K, 0% used [0x00000007b5580000,0x00000007b5580000,0x00000007c0000000)
ParOldGen total 2796544K, used 16K [0x00000006c0000000, 0x000000076ab00000, 0x000000076ab00000)
object space 2796544K, 0% used [0x00000006c0000000,0x00000006c0004000,0x000000076ab00000)
Metaspace used 20827K, capacity 21114K, committed 21248K, reserved 1067008K
class space used 2916K, capacity 3027K, committed 3072K, reserved 1048576K
2021-06-22T16:04:51.247+0800: 6.144: [Full GC (Metadata GC Threshold) [PSYoungGen: 23321K->0K(1223168K)] [ParOldGen: 16K->22263K(2796544K)] 23337K->22263K(4019712K), [Metaspace: 20827K->20826K(1067008K)], 0.0839136 secs] [Times: user=0.17 sys=0.03, real=0.08 secs]
Heap after GC invocations=2 (full 1):
PSYoungGen total 1223168K, used 0K [0x000000076ab00000, 0x00000007c0000000, 0x00000007c0000000)
eden space 1048576K, 0% used [0x000000076ab00000,0x000000076ab00000,0x00000007aab00000)
from space 174592K, 0% used [0x00000007aab00000,0x00000007aab00000,0x00000007b5580000)
to space 174592K, 0% used [0x00000007b5580000,0x00000007b5580000,0x00000007c0000000)
ParOldGen total 2796544K, used 22263K [0x00000006c0000000, 0x000000076ab00000, 0x000000076ab00000)
object space 2796544K, 0% used [0x00000006c0000000,0x00000006c15bdf88,0x000000076ab00000)
Metaspace used 20826K, capacity 21112K, committed 21248K, reserved 1067008K
class space used 2916K, capacity 3026K, committed 3072K, reserved 1048576K
}
日志参数说明
- CommandLine flags:命令行标识(构建代码Java 命令行参数)
- -XX:InitialHeapSize=4294967296 默认初始化堆内存
- -XX:MaxHeapSize=4294967296 最大堆内存大小 -XX:InitialHeapSize and -XX:MaxHeapSize are often set to the same value. 最好设置同样大小,详情见官文:http://docs.oracle.com/javase/8/docs/technotes/guides/vm/gctuning/index.html.
- -XX:+PrintClassHistogram 按Ctrl+c 打印印类实例直方图
- -XX:+PrintGC 打印每一次gc信息
- -XX:+PrintGCApplicationStoppedTime 允许打印暂停(例如GC暂停)持续的时间(eg信息:2021-06-21T22:16:40.590+0800: 4.801: Total time for which application threads were stopped: 0.0004071 seconds)
- -XX:+PrintGCDateStamps 允许在每个GC打印日期戳
- -XX:+PrintGCDetails 支持在每个GC打印详细消息
- -XX:+PrintGCTimeStamps允许在每个GC打印时间戳
- -XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息
- -XX:+PrintTenuringDistribution 允许打印使用年限信息,可见官方文档(eg信息:Desired survivor size 178782208 bytes, new threshold 7 (max 15),所需幸存者大小178782208字节,新阈值7(最大15)
- -XX:ThreadStackSize=512 设置线程栈大小
- -XX:+UseCompressedClassPointers
- -XX:+UseCompressedOops禁止使用压缩指针。默认情况下,此选项处于启用状态,当Java堆大小小于32gb时,将使用压缩指针。启用此选项后,对象引用将表示为32位偏移量,而不是64位指针,这通常会在Java堆大小小于32 GB的情况下运行应用程序时提高性能。此选项仅适用于64位JVM**-XX:+UseParallelGC** 允许使用并行清除垃圾收集器(Parallel Scavenge收集器)(也称为吞吐量收集器)通过利用多个处理器来提高应用程序的性能
JVM参数官方说明文档
https://docs.oracle.com/javase/8/docs/technotes/tools/unix/java.html
GC发生前的堆内存参数解读
{Heap before GC invocations=1 (full 0): #GC发生前的堆内存信息,调用一次 full GC 0次
PSYoungGen PS(Parallel Scavenge收集器)新生代内存大小
eden 伊甸园区内存大小
from from区内存大小
to to区内存大小
ParOldGen Par(Parallel Old收集器)老年代内存大小
Metaspace 元空间内存
class space Java中压缩指针(Compressed pointers)的含义是允许在64bit的平台上用32bit地址来引用对象,其实现原理是64bit的基址加上32bit的偏移地址,最终生成64bit的虚拟地址,然后操作系统页表寻址找到64bit的物理地址完成寻址
used 2916K,apacity 21112K, committed 21248K, reserved 1067008K
其中used和capacity是从类加载器的角度来衡量的,而committed和reserved是从操作系统地址空间的角度来衡量的:
- used:是分配给所有类加载器的metachunk中用来存储元数据的部分的大
- capacity:分配给所有类加载器的metachunk的大小,包含每个metachunk的head、used、wasted和current metachunk的free部分
- committed:向OS申请的内存中已经分配物理内存的大小,包含VirtualSpaceList中所有node已经commit的部分(也就是非当前node+当前node commit的部分),或者说所有类加载器的capacity+全局空闲链表Chunk Manager+硬件预留HWM margin
- reserved: JVM进程虚拟地址空间的部分,像class metaspace默认CompressedClassSpaceSize是1GB,所以reserved就是1GB
[0x000000076ab00000,0x000000076ab00000,0x00000007aab00000)
三个数字在HotSpot里分别称为low_boundary、high、high_boundary。
- low_boundary: reserved space的最低地址边界;通常也跟“low”相等,这是commited space的最低地址边界
- high: commited space的最高地址边界
- high_boundary: reserved space的最高地址边界。
GC详细信息
[PSYoungGen: 796938K->23321K(1223168K)] 796938K->23337K(4019712K), 0.0630982 secs] [Times: user=0.06 sys=0.01, real=0.06 secs]
参考链接:Java8GC类型
-
年轻代发生一次Minor GC ,这里我们要知道Minor GC的触发条件:
Minor GC/Young GC的触发条件: 年轻代空间不足,触发Minor GC,具体就是指的是年轻代的Eden区满了,Survivor区满了不会触发GC,每次触发Minor GC,都会顺带处理Survivor区,复制调配from-to区。
Minor GC的特点:非常频繁切速度快,会引发STW(Stop the World),暂停用户线程,等待GC结束之后用户线程恢复运行 -
紧接着发生第二次Full GC
2021-06-22T16:04:51.247+0800: 6.144: [Full GC (Metadata GC Threshold) [PSYoungGen: 23321K->0K(1223168K)] [ParOldGen: 16K->22263K(2796544K)] 23337K->22263K(4019712K), [Metaspace: 20827K->20826K(1067008K)], 0.0839136 secs] [Times: user=0.17 sys=0.03, real=0.08 secs]
Major GC/Old GC的触发条件: 对象从老年代消失则产生了Major GC/Old GC,老年代空间不足,则先触发Minor GC ,空间仍然不足则触发Major GC
Major GC的特点:比Minor GC慢十倍以上,STW时间更长
Full GC的触发条件:
- 显示调用System.gc,系统建议执行GC,但是不会必然执行;
- 老年代空间不足;
- 方法区空间不足Minor GC晋升老年代的对象大小大于老年代的可用内存大小
- minor gc之后进入老年代的平均大小大于老年代的可用内存
- minor gc时,向to区复制对象内存大于to区内存,直接向老年代转移,老年代内存任然不能装下该对象
结论:
-
首先查看gc之前的堆内存(如下图),存在Young GC之后存在大量对象晋升到老年代
-
并且Full GC 发生之后,回收老年代内存数量很小的情况出现(如下图),说明存在大量的对象引用没有释放,或者大量的对象晋升到老年代
-
在年轻代触发GC之后,又有大量的内存被占用,说明说明代码中具有较大的内存占用对象被创建(eg:查询大数据量的数据)
-
并且老年代GC之后也是回收效率很低,有两种情况:大量老年代对象未释放;新的对象晋升到老年代,并且从日志中GC之后年轻代大量晋升到老代(晋升老年代的条件只有两种情况:达到晋升年龄(看日志代码对应不具备这样的条件),大数据对象直接晋升老年代 )推断代码中应该是存在大数据对象被创建,代码存在中大量查询大量数据的操作,结果查看代码确实存在这样的问题
-
但是发生Full GC的日志后面显示Metadata GC Threshold,有想过是否是对象达到元空间的阈值触发老了Full GC,首先放到元空间的数据我们需要清除是那些数据(存储每个类的信息(包括类的名称、方法信息、字段信息)、静态变量、常量、运行时常量池(Runtime Constant Pool)以及编译器编译后的代码等),推断有可能是加载类中存在占用较大内存的字段,或则大字符串常量,反查代码确实存在大量的sql拼接操作(此处还需考证)
-
随后再开heaphero 分析文件,以及Jprofile 分析的dump 文件,基本能和以上推断吻合,所以就此展开代码优化
在排查问题过程中用到的工具:
其他常用的GC分析工具:
- GCViewer
- GCHisto
- GCLogViewer
- Hpjmeter
- garbagecat