java gc日志的基本知识
回顾一下gc日志的基本知识,下面是一条gc日志:
33.125:[GC[DefNew: 3324k->152k(3712k), 0.0025925 secs] 3324k>152k(11904k),0.0031680 secs]
从左至右,各个信息的意思为:
33.125:自虚拟机启动以来经过的秒数,单位为秒;GC:垃圾收集的停顿类型为不需要STW(Stop The World )。如果是Full GC说明发生了STW。如果是Full GC (System)说明是调用System.gc()方法所触发的收集。DefNew:表示GC发生的区域在新生代。这个名称和所使用的收集器密切相关。可以有Tenured、Perm、ParNew、PSYoungGen等等。其中hotspot虚拟机使用的是PSYoungGen代表新生代3324k->152k(3712k):GC前该区域(DefNew)已使用容量->GC后该区域已使用容量(该内存区域总容量)0.0025925 secs:该内存区域(DefNew)GC所占用的时间。3324k->152k(11904k):GC前Java堆已使用容量->GC后Java堆已使用容量(Java堆总容量)本次博主遇到的内存问题是在使用spring batch做数据迁移时遇到的,在使用springbatch迁移数据时,发现了虚拟机内存用量不断增大的现象,于是将gc日志存了下来,并且通过jconsole截取了内存变化的情况。使用的vm运行参数为:
-XX:InitialHeapSize=266386688 -XX:MaxHeapSize=4262187008 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC
JConsole通过JConsole监测到的memory使用情况如下.
堆内存的整体情况如下图所示:
老年代的整体情况如下图所示
年轻代eden space如下
搜索公众号Linux中文社区后台回复“命令行”,获取一份惊喜礼包。
VisualVmJconsole当中的信息比较粗略,作为JConsole的升级版,VisualVm提供了更多的信息。
堆内存信息:
上图中可以清楚的看出元空间metaspace占的大小是固定的,而老年代则占据了相当大的内存空间。年轻代则是相对不停在动态变化的区域。因此,老年代的内存是我们要重点分析的。
这是整个内存区域的折线图展示。
我们可以使用Java VisualVM浏览堆heap dump文件的内容,并查看堆中已分配的对象。对我们需要进行heap dump分析的java程序点右键就能找到heap dump选项。一次heap dump是特定时间点Java虚拟机(JVM)堆中所有对象的一个快照。
JVM为所有类实例和数组对象在堆中分配内存。当不再需要对象且没有对象的引用时,垃圾收集器将回收堆内存。通过检查堆,可以找到创建对象的位置,并查找对这些对象的引用。如果JVM无法从堆中删除不需要的对象,Java VisualVM可以帮助我们找到对象的最近的GC Root。博主dump出来的结果如下:
Summary.
java VisualVm默认会展示Summary界面的信息,主要显示执行heap dump时的运行环境以及其他系统属性。GC Roots这一垃圾回收的概念也被展示在这里。
classClass视图显示了类的列表以及该类引用的实例的数量和百分比。通过右键单击名称并选择查看nstances,可以查看特定类的实例列表。
可以发现占据最大堆内存的是一个byte类型的数组。另外有句题外话,在上图中我们发现String和char[]这两个类的数量几乎是相当的,这从侧面印证了String内部是由Char数组实现的。
它对应的实例对象instance信息如下:
注意,这里有一个非常重要的问题需要弄清楚。在上面的截图当中,虽然占内存最多的是Byte类型的对象,但是这绝不意味着所有的byte对象都是由同一个模块或类所持有的。
例如,上面截图当中的instance类型是HRequestPacket,这是jdbc写数据时用到的一个类。但是不能就此判断就是该类导致了这个问题。因为除了这个类,还有很多其他的类里面有byte类型的数据引用。
搜索公众号后端架构师后台回复“架构整洁”,获取一份惊喜礼包。
理解了这一点对于分析这个问题至关重要,因此,如果我们能分析出是哪个类的对象占据了绝大多数的byte类型引用,则我们就找到了问题的关键。
GC日志gc日志如下:
Java HotSpot(TM) 64-Bit Server VM (25.151-b12) for windows-amd64 JRE (1.8.0_151-b12), built on Sep 5 2017 19:33:46 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 16649168k(5641848k free), swap 41814992k(16763352k free)
CommandLine flags: -XX:InitialHeapSize=266386688 -XX:MaxHeapSize=4262187008 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC
2019-03-28T18:02:49.809+0800: 3.175: [GC (Allocation Failure) [PSYoungGen: 65536K->7435K(76288K)] 65536K->7451K(251392K), 0.0132004 secs] [Times: user=0.00 sys=0.02, real=0.01 secs]
2019-03-28T18:02:52.006+0800: 5.371: [GC (Allocation Failure) [PSYoungGen: 72971K->10722K(76288K)] 72987K->12689K(251392K), 0.0207831 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
2019-03-28T18:02:52.097+0800: 5.463: [GC (Metadata GC Threshold) [PSYoungGen: 13589K->8536K(76288K)] 15555K->10511K(251392K), 0.0159315 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
2019-03-28T18:02:52.114+0800: 5.479: [Full GC (Metadata GC Threshold) [PSYoungGen: 8536K->0K(76288K)] [ParOldGen: 1974K->8439K(88064K)] 10511K->8439K(164352K), [Metaspace: 20723K->20723K(1067008K)], 0.0733626 secs] [Times: user=0.09 sys=0.03, real=0.07 secs]
2019-03-28T18:02:54.666+0800: 8.031: [GC (Allocation Failure) [PSYoungGen: 65536K->5668K(123904K)] 73975K->14116K(211968K), 0.0442485 secs] [Times: user=0.13 sys=0.00, real=0.05 secs]
2019-03-28T18:03:01.638+0800: 15.004: [GC (Allocation Failure) [PSYoungGen: 123428K->10746K(137216K)] 131876K->20995K(225280K), 0.0197362 secs] [Times: user=0.00 sys=0.02, real=0.02 secs]
2019-03-28T18:03:02.068+0800: 15.433: [GC (Metadata GC Threshold) [PSYoungGen: 40440K->9781K(222208K)] 50689K->20038K(310272K), 0.0189468 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
2019-03-28T18:03:02.087+0800: 15.452: [Full GC (Metadata GC Threshold) [PSYoungGen: 9781K->0K(222208K)] [ParOldGen: 10256K->17742K(114688K)] 20038K->17742K(336896K), [Metaspace: 34221K->34221K(1079296K)], 0.0911808 secs] [Times: user=0.31 sys=0.00, real=0.09 secs]
2019-03-28T18:03:06.921+0800: 20.287: [GC (Allocation Failure) [PSYoungGen: 206848K->13185K(221696K)] 224590K->30928K(336384K), 0.0362549 secs] [Times: user=0.11 sys=0.00, real=0.04 secs]
2019-03-28T18:03:11.063+0800: 24.429: [GC (Allocation Failure) [PSYoungGen: 220033K->15854K(367104K)] 237776K->38236K(481792K), 0.0308660 secs] [Times: user=0.06 sys=0.02, real=0.03 secs]
2019-03-28T18:08:09.294+0800: 322.661: [Full GC (Ergonomics) [PSYoungGen: 293373K->126822K(794112K)] [ParOldGen: 1012403K->1154394K(1639424K)] 1305776K->1281217K(2433536K), [Metaspace: 62153K->62153K(1105920K)], 3.9747741 secs] [Times: user=11.53 sys=0.23, real=3.97 secs]
GC日志分析前两行打出的是虚拟机的基本信息和使用的vm参数。其中InitialHeapSize=266386688,即我们设定虚拟机的堆初始化大小为2.5G左右。MaxHeapSize=4262187008,即最大的堆大小为4G。
下面我们来挑几条gc日志进行分析
第一条:
2019-03-28T18:02:49.809+0800: 3.175: [GC (Allocation Failure) [PSYoungGen: 65536K->7435K(76288K)] 65536K->7451K(251392K), 0.0132004 secs] [Times: user=0.00 sys=0.02, real=0.01 secs]
2019-03-28T18:02:49.809+0800 : gc日志记录时间3.175 :gc发生时,虚拟机运行了多少秒GC (Allocation Failure) :发生了一次垃圾回收,若前面有Full则表明是Full GC,没有Full的修饰表明这是一次Minor GC 。注意它不表示只GC新生代,括号里的内容是gc发生的原因,这里的Allocation Failure的原因是年轻代中没有足够区域能够存放需要分配的数据而失败,。PSYoungGen:使用的垃圾收集器的名字。65536K->7435K(76288K) :垃圾收集前后的年轻代内存使用情况,其中前面的65536kb为gc之前的使用量,7435kb为gc之后的内存使用量。括号里的76288k为该内存区域的总量。65536K->7451K(251392K) : 垃圾收集前后整个堆内存的使用情况,括号里的为整个可以的堆内存的容量。0.0132004 secs :整个GC过程持续时间[Times: user=0.00 sys=0.02, real=0.01 secs] :分别表示用户态耗时,内核态耗时和总耗时。也是对gc耗时的一个记录。第二条:
019-03-28T18:02:52.097+0800: 5.463: [GC (Metadata GC Threshold) [PSYoungGen: 13589K->8536K(76288K)] 15555K->10511K(251392K), 0.0159315 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
也是一次minor gc,但是与前两次的gc原因不一样,这次的gc原因是:Metadata GC Threshold。Metadata即元数据的意思。我们可以看出这是与虚拟机的元数据区有关系的一次gc。元数据区,在jdk1.8以前又叫永久代,从JDK8开始,永久代(PermGen)的概念被废弃掉了,取而代之的就是这里的称为Metaspace的存储空间。
元空间和永久代是虚拟机对方法区这个概念的一个具体实现。对于元空间而言,这一块空间是存在本地内存当中的。因此,默认情况下,元空间的大小仅受本地内存限制,但我们可以通过参数来指定元空间的大小。
这里元空间发生gc,说明元空间的内存不够了,到达了阀值。对元空间进行了一次垃圾回收,回收之前是13489k,回收之后是8536k。
第三条:
2019-03-28T18:02:52.114+0800: 5.479: [Full GC (Metadata GC Threshold) [PSYoungGen: 8536K->0K(76288K)] [ParOldGen: 1974K->8439K(88064K)] 10511K->8439K(164352K), [Metaspace: 20723K->20723K(1067008K)], 0.0733626 secs] [Times: user=0.09 sys=0.03, real=0.07 secs]
在元空间gc之后,紧接着发生了一次Full GC,且触发原因也是元空间不足。
[PSYoungGen: 8536K->0K(76288K)] :年轻代进行了一次gc[ParOldGen: 1974K->8439K(88064K)] :老年代进行了一次gc[Metaspace: 20723K->20723K(1067008K)] :元空间(方法区)发生了一次gc,但是值得注意的是,gc前后内存使用情况并没有发生任何改变。同时,元空间总的可使用的内存为:1gb。后面又发生了两次full gc,且与这次full gc基本是一致的,但是不同的是元空间使用量在不停变大。
第二次full gc的日志为:
2019-03-28T18:03:02.087+0800: 15.452: [Full GC (Metadata GC Threshold) [PSYoungGen: 9781K->0K(222208K)] [ParOldGen: 10256K->17742K(114688K)] 20038K->17742K(336896K), [Metaspace: 34221K->34221K(1079296K)], 0.0911808 secs] [Times: user=0.31 sys=0.00, real=0.09 secs]
其中空间信息为:[Metaspace: 34221K->34221K(1079296K)]
第三次full gc时的日志为:
2019-03-28T18:04:50.386+0800: 123.753: [Full GC (Metadata GC Threshold) [PSYoungGen: 32080K->0K(513536K)] [ParOldGen: 97445K->114064K(259072K)] 129526K->114064K(772608K), [Metaspace: 57009K->57009K(1101824K)], 0.4012776 secs] [Times: user=0.70 sys=0.00, real=0.40 secs]
其中元空间信息为:[Metaspace: 57009K->57009K(1101824K)]
可以看到元空间的使用量一直在增大,且没有被回收。同时,老年代的使用内存在一直变大,gc的同时,老年代又不断有新的对象进入。对老年代的gc并没有降低老年代的内存使用量,这与通过jconsle看到的信息也是一致的。
在这三次full gc之后的第四次full gc日志如下:
2019-03-28T18:07:36.876+0800: 290.243: [Full GC (Ergonomics) [PSYoungGen: 58860K->52656K(859648K)] [ParOldGen: 757683K->757303K(1154560K)] 816543K->809960K(2014208K), [Metaspace: 62060K->62053K(1105920K)], 4.0586369 secs] [Times: user=11.55 sys=0.16, real=4.06 secs]
注意,这次full gc的原因发生了变化,为Full GC (Ergonomics),它的意思是执行了一次全局gc。
且从执行效果[ParOldGen: 757683K->757303K(1154560K)]来看,本次full gc从内存使用情况来看几乎没有起到作用。这有两个可能的原因:
gc本身没有回收多少对象gc回收了很多对象,但同时又有更多的对象进入老年代同时,元数据区使用量继续变大。
从第四次full gc开始,之后的full gc全部变成了全局Ergonomics gc。
第五次:[ParOldGen: 1012403K->1154394K(1639424K)],从这次开始老年代超过了初始容量,开始变大
第六次:[ParOldGen: 1714731K->1714877K(2346496K)] ,老年代容量继续变大,元空间几乎不变。
第七次:[ParOldGen: 2098093K->2103707K(2776064K)], 老年代容量继续变大,元空间几乎不变
这之后随着程序继续运行,但是full gc不再出现,只出现minor gc, 但我们观察到,可用容量已达到4g,几乎达到了总容量,且老年代的内存使用量不再发生变化,这说明也许这时候老年代已经无法再进行gc。
以上就是对此次gc日志的分析。至于每次gc的根本原因,则需要结合自己的代码进行分析,博主这次的原因在于在读数据时一次将所有数据读入了内存当中。