Arnold's Blog
Arnold Shu
2021-06-28
目录

记一次GC 排查及优化

# 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
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47

# 日志参数说明

  • 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. (opens new window)
  • -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 (opens new window)

# 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]
1

1

参考链接：Java8GC类型 (opens new window)

  1. 年轻代发生一次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结束之后用户线程恢复运行

  2. 紧接着发生第二次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]
1

2

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区内存，直接向老年代转移，老年代内存任然不能装下该对象

结论：

  1. 首先查看gc之前的堆内存（如下图），存在Young GC之后存在大量对象晋升到老年代 3

  2. 并且Full GC 发生之后,回收老年代内存数量很小的情况出现（如下图），说明存在大量的对象引用没有释放，或者大量的对象晋升到老年代45

  3. 在年轻代触发GC之后，又有大量的内存被占用，说明说明代码中具有较大的内存占用对象被创建（eg:查询大数据量的数据）6

  4. 并且老年代GC之后也是回收效率很低，有两种情况：大量老年代对象未释放；新的对象晋升到老年代，并且从日志中GC之后年轻代大量晋升到老代(晋升老年代的条件只有两种情况：达到晋升年龄（看日志代码对应不具备这样的条件），大数据对象直接晋升老年代 )推断代码中应该是存在大数据对象被创建，代码存在中大量查询大量数据的操作，结果查看代码确实存在这样的问题7

  5. 但是发生Full GC的日志后面显示Metadata GC Threshold，有想过是否是对象达到元空间的阈值触发老了Full GC，首先放到元空间的数据我们需要清除是那些数据（存储每个类的信息（包括类的名称、方法信息、字段信息）、静态变量、常量、运行时常量池(Runtime Constant Pool)以及编译器编译后的代码等）,推断有可能是加载类中存在占用较大内存的字段，或则大字符串常量，反查代码确实存在大量的sql拼接操作（此处还需考证）8

  6. 随后再开heaphero 分析文件，以及Jprofile 分析的dump 文件，基本能和以上推断吻合，所以就此展开代码优化 9 10 11 12

  7. 在排查问题过程中用到的工具：

其他常用的GC分析工具:

  • GCViewer
  • GCHisto
  • GCLogViewer
  • Hpjmeter
  • garbagecat
#JVM#OOM
上次更新: 2023/12/15, 14:53:20
函数式编程(JAVA)
JVM浅析总结(JVM的生命周期)

← JVM浅析总结(JVM的生命周期)→

最近更新
01
Linux 的常用命令
10-22
02
程序设计中SPI和API
10-22
03
IDEA 使用技巧
10-15
更多文章>
Theme by Vdoing | Copyright © 2017-2024 Arnold Shu | CC BY-SA 4.0 License