「java开启gc日志」java 打印gc日志 影响性能

今天给各位分享java开启gc日志的知识，其中也会对java 打印gc日志 影响性能进行解释，如果能碰巧解决你现在面临的问题，别忘了关注本站，现在开始吧！

本文目录一览：

• 1、java gc日志在哪
• 2、JVM GC 日志详解
• 3、理解CMS GC日志
• 4、java gc的日志在哪里看？
• 5、JVM-GC日志查看分析
• 6、GC日志查看和分析

java gc日志在哪

-XX:+PrintGC 输出GC日志

-XX:+PrintGCDetails 输出GC的详细日志

-XX:+PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式）

-XX:+PrintGCDateStamps 输出GC的时间戳（以日期的形式，如 2013-05-04T21:53:59.234+0800）

-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息

-Xloggc:../logs/gc.log 日志文件的输出路径

JVM GC 日志详解

本文采用的JDK版本：

设置JVM GC格式日志的主要参数包括如下8个：

本文假设读者已经熟悉JVM 内存结构。

如果想开启GC日志的信息，可以通过设置如下的参数任一参数：

如果只设置 -XX:+PrintGC 那么打印的日志如下所示：

1、 GC 表示是一次YGC（Young GC）

2、 Allocation Failure 表示是失败的类型

3、 68896K-5080K 表示年轻代从68896K降为5080K

4、 256000K 表示整个堆的大小

5、 0.0041139 secs 表示这次GC总计所用的时间

在JDK 8中， -verbose:gc 是 -XX:+PrintGC 一个别称，日志格式等价与： -XX:+PrintGC ，。

不过在 JDK 9 中 -XX:+PrintGC被标记为 deprecated 。

-verbose:gc 是一个标准的选项， -XX:+PrintGC 是一个实验的选项，建议使用 -verbose:gc 替代 -XX:+PrintGC

参考： Difference between -XX:+PrintGC and -verbose:gc

1、 GC 表示是一次YGC（Young GC）

2、 Allocation Failure 表示是失败的类型

3、PSYoungGen 表示年轻代大小

4、 53248K-2176K 表示年轻代占用从 53248K 降为 2176K

5、 59392K 表示年轻带的大小

6、 58161K-7161K 表示整个堆占用从 53248K 降为 2176K

7、 256000K 表示整个堆的大小

8、 0.0039189 secs 表示这次GC总计所用的时间

9、 [Times: user=0.02 sys=0.01, real=0.00 secs] 分别表示，用户态占用时长，内核用时，真实用时。

时间保留两位小数，四舍五入。

如果加上 -XX:+PrintGCTimeStamps 那么日志仅仅比1.1介绍的最前面多了一个时间戳： 1.963 ， 表示从JVM启动到打印GC时刻用了1.963秒。

如果加上 -XX:+PrintGCDateStamps 那么日志仅仅比1.1介绍的最前面多了一个日期时间： 2019-03-05T16:56:15.108+0800 ， 表示打印GC的时刻的时间是 2019-03-05T16:56:15.108+0800 。+0800表示是东8区。

这个参数开启后，

使用如下参数 -verbose:gc -XX:+PrintHeapAtGC -Xmn64M -Xms256M -Xmx256M

打印日志如下：

由此可以看出在，打印如下日志前后

详细打印出了日志信息

invocations 表示GC的次数，每次GC增加一次，每次GC前后的invocations相等

1、 Heap before GC invocations=1 表示是第1次GC调用之前的堆内存状况

2、 {Heap before GC invocations=1 (full 0): 表示是第1次GC调用之后的堆内存状况

如果使用该参数 -Xloggc 则默认开启如下两个参数

如果启动参数如下： -Xloggc:gc.log -Xmn64M -Xms256M -Xmx256M 则日志格式如下所示

gc.log 也可以指定绝对的路径。

在gc.log最前面还会默认打印系统的JDK版本与启动的参数

此设置 -XX:+PrintReferenceGC可以打印出SoftReference，WeakReference，FinalReference，PhantomReference，JNI Weak Reference几种引用的数量，以及清理所用的时长，该参数在进行YGC调优时可以排上用场。

具体可以参考占小狼的一篇实战： 一次 Young GC 的优化实践（FinalReference 相关）

CMS日志分为两个STW(stop the world)

分别是 init remark （1） 与 remark （7）两个阶段。一般耗时比YGC长约10倍（个人经验）。

（1）、 [GC (CMS Initial Mark) [1 CMS-initial-mark: 19498K(32768K)] 36184K(62272K), 0.0018083 secs][Times: user=0.01 sys=0.00, real=0.01 secs]

会STO(Stop The World)，这时候的老年代容量为 32768K， 在使用到 19498K 时开始初始化标记。耗时短。

（2）、 [CMS-concurrent-mark-start]

并发标记阶段开始

（3）、 [CMS-concurrent-mark: 0.011/0.011 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]

并发标记阶段花费时间。

（4）、 [CMS-concurrent-preclean-start]

并发预清理阶段，也是与用户线程并发执行。虚拟机查找在执行并发标记阶段新进入老年代的对象(可能会有一些对象从 新生代 晋升到老年代， 或者有一些对象被分配到老年代)。通过重新扫描，减少下一个阶段”重新标记”的工作，因为下一个阶段会Stop The World。

（5）、 [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]

并发预清理阶段花费时间。

（6）、 [CMS-concurrent-abortable-preclean-start] CMS: abort preclean due to time [CMS-concurrent-abortable-preclean: 0.558/5.093 secs][Times: user=0.57 sys=0.00, real=5.09 secs]

并发可中止预清理阶段，运行在并行预清理和重新标记之间，直到获得所期望的eden空间占用率。增加这个阶段是为了避免在重新标记阶段后紧跟着发生一次垃圾清除

（7）、 [GC (CMS Final Remark) [YG occupancy: 16817 K (29504 K)][Rescan (parallel) , 0.0021918 secs][weak refs processing, 0.0000245 secs][class unloading, 0.0044098 secs][scrub symbol table, 0.0029752 secs][scrub string table, 0.0006820 secs][1 CMS-remark: 19498K(32768K)] 36316K(62272K), 0.0104997 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

会STW(Stop The World)，收集阶段，这个阶段会标记老年代全部的存活对象，包括那些在并发标记阶段更改的或者新创建的引用对象

（8）、 [CMS-concurrent-sweep-start]

并发清理阶段开始，与用户线程并发执行。

（9）、 [CMS-concurrent-sweep: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

并发清理阶段结束，所用的时间。

（10）、 [CMS-concurrent-reset-start]

开始并发重置。在这个阶段，与CMS相关数据结构被重新初始化，这样下一个周期可以正常进行。

（11）、 [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

并发重置所用结束，所用的时间。

参考：

Geek-Yan : JVM 学习笔记(四) CMS GC日志详解

设置JVM GC 性能的有如下参数

新生代大小官网推荐的大小是 3/8 , 如果设置太小，比如 1/10会 导致 Minor GC 与 Major GC 次数增多。

其中n的大小为区间为[0,15],如果高于15，JDK7 会默认15，JDK 8会启动报错

发生在CMS GC运行期间，详情参考：

JVM 调优 —— GC 长时间停顿问题及解决方法

GC的悲观策略

发生在Minor GC期间

理解CMS GC日志

本文以idea的启动日志为例解读CMS收集器的GC日志

在 idea64.exe.vmoptions 文件中可以看到idea的启动参数，下面是初始启动参数配置

其中 -XX:+UseConcMarkSweepGC 表示使用 ParNew + CMS + Serial Old 收集器组合进行内存回收，Serial收集器是作为CMS收集器出现Concurrent Model Failure失败后的后备收集器，相当于替补。

接下来需要添加启动参数来打印idea的GC日志，JVM提供的几个主要的GC日志参数如下：

综上，我们在 idea64.exe.vmoptions 文件中添加如下配置参数打印GC信息

然后重启idea，就能在对应的D盘根目录下找到生成的gc.log日志。

由于日志内容过长，一下子全展示出来太乱而不方便阅读，这里对日志中每个不用的现象输出分别做出讲解。

首先文件的最开头的信息如下：

这个很好理解，就是显示了当前程序运行的环境，当前的jdk版本为1.8。

接下来的输出信息如下：

这部分显示了这次JVM的启动参数配置，我们在idea64.exe.vmoptions配置的信息也会在这里打印出来，我们可以从这里看出很多默认配置，比如 -XX:MaxTenuringThreshold=6 这个参数，表示Survivor区的对象晋升老年代的年龄阈值为6，这个值在JDK 1.8之前默认为15。

再下面就是应用的GC信息了，不同的内存区域（新生代和老年代）发生的GC日志信息有所不同，下面一一举例。

最前面的 2019-03-01T13:38:04.037+0800: 0.867: 是固定的， 2019-03-01T13:38:04.037+0800 表示GC发生的日期花间， 0.867 表示本次gc与JVM启动时的相对时间，单位为秒。

[GC (Allocation Failure) 这里的 GC 表示这是一次垃圾回收，但并不能单凭这个就判断这是依次Minor GC，下文会说到CMS的标识为 [GC (CMS Initial Mark) 和 [GC (CMS Final Remark) ，同样是 GC CMS的却是是Major GC；括号中的 Allocation Failure 表示gc的原因，新生代内存不足而导致新对象内存分配失败。

再后面的 [ParNew: 表示本次gc使用的垃圾收集器为ParNew，我们知道ParNew是针对新生代的垃圾收集器，从这可以看出本次gc是Minor GC。后面紧跟着的 34944K-4352K(39296K) 的含义是 GC前该内存区域已使用容量 - GC后该内存区域已使用容量（该内存区域总容量） ，再后面的 0.0138186 secs 表示该内存区域GC所占用的时间，单位为秒。

再后面的 34944K-6355K(126720K), 0.0141834 secs 表示收集前后整个堆的使用情况， 0.0141834 secs 表示本次GC的总耗时，包括把年轻代的对象转移到老年代的时间。

最后的 [Times: user=0.06 sys=0.00, real=0.02 secs] 表示GC事件在不同维度的耗时，单位为秒。这里面的user、sys和real与Linux的time命令所输出的时间含义一致，分别表示用户态消耗的CPU时间、内核态消耗的CPU时间和操作从开始到结束所经过的等待耗时，例如等待磁盘I/O、等待线程阻塞，而CPU时间不包括这些耗时，但当系统有多CPU或者多核的话，多线程操作会叠加这些CPU时间，所以有时候user或sys时间超过real时间也是完全正确的。

这里先要明确Minor GC、Major GC和Full GC的区别：

老年代由CMS收集器执行的Major GC相对比较复杂，包括初始标记、并发标记、重新标记和并发清除4个阶段，下面的gc日志也详细地描述了各个阶段的信息。

为了更清晰的观察各个阶段的日志信息，对上面的日志信息重新排版并添加注释，如下：

下面对上图中各个阶段的日志进行分析

初始标记阶段（CMS initial mark）

[GC (CMS Initial Mark) 表示这是CMS开始对老年代进行垃圾圾收集的初始标记阶段，该阶段从垃圾回收的“根对象”开始，且只扫描直接与“根对象”直接关联的对象，并做标记，需要暂停用户线程（Stop The Word，下面统称为STW），速度很快。 104208K(126116K) 表示当前老年代的容量为126116K，在使用了104208K时开始进行CMS垃圾回收。可以计算下这个比例，104208 / 126116约等于0.83，可以大概推算出CMS收集器的启动内存使用阈值。

后面的 108824K(165412K), 0.0055322 secs 表示当前整个堆的内存使用情况和本次初始标记耗费的时间，最后的 [Times: user=0.00 sys=0.00, real=0.00 secs] 上文已经讲过，下文将不再重复。

并发标记阶段（CMS concurrent mark）

该阶段进行了细分，但都是和用户线程并发进行的

[CMS-concurrent-mark 表示并发标记阶段，会遍历整个年老代并且标记活着的对象，后面的 0.154/0.155 secs 表示该阶段持续的时间和时钟时间，耗时0.15秒，可见耗时是比较长的。

由于该阶运行的过程中用户线程也在运行，这就可能会发生这样的情况，已经被遍历过的对象的引用被用户线程改变，如果发生了这样的情况，JVM就会标记这个区域为Dirty Card。

[CMS-concurrent-preclean 阶段会把上一个阶段被标记为Dirty Card的对象以及可达的对象重新遍历标记，完成后清楚Dirty Card标记。另外，一些必要的清扫工作也会做，还会做一些final remark阶段需要的准备工作。

[CMS-concurrent-abortable-preclean 并发预清理，这个阶段尝试着去承担接下来STW的Final Remark阶段足够多的工作，由于这个阶段是重复的做相同的事情直到发生aboart的条件（比如：重复的次数、多少量的工作、持续的时间等等）之一才会停止。这个阶段很大程度的影响着即将来临的Final Remark的停顿。

从后面的 1.190/1.707 secs 显示这个阶段持续了1秒多的时间，相当的长。

重新标记阶段（CMS remark）

该阶段同样被细分为多个子阶段

[GC (CMS Final Remark) 表示这是CMS的重新标记阶段，会STW，该阶段的任务是完成标记整个年老代的所有的存活对象，尽管先前的pre clean阶段尽量应对处理了并发运行时用户线程改变的对象应用的标记，但是不可能跟上对象改变的速度，只是为final remark阶段尽量减少了负担。

[YG occupancy: 24305 K (39296 K)] 表示年轻代当前的内存占用情况，通常Final Remark阶段要尽量运行在年轻代是足够干净的时候，这样可以消除紧接着的连续的几个STW阶段。

[Rescan (parallel) , 0.0103714 secs] 这是整个final remark阶段扫描对象的用时总计，该阶段会重新扫描CMS堆中剩余的对象，重新从“根对象”开始扫描，并且也会处理对象关联。本次扫描共耗时 0.0103714s。

[weak refs processing, 0.0006267 secs] 第一个子阶段，表示对弱引用的处理耗时为0.0006267s。

[class unloading, 0.0368915 secs] 第二个子阶段，表示卸载无用的类的耗时为0.0368915s。

[scrub symbol table, 0.0486196 secs] 最后一个子阶段，表示清理分别包含类级元数据和内部化字符串的符号和字符串表的耗时。

[1 CMS-remark: 108093K(126116K)] 表示经历了上面的阶段后老年代的内存使用情况。再后面的 132398K(165412K), 0.1005635 secs 表示final remark后整个堆的内存使用情况和整个final remark的耗时。

并发清除阶段（CMS concurrent sweep）

该阶段和用户线程并发执行，不会STW，作用是清除之前标记阶段没有被标记的无用对象并回收内存。整个过程分为两个子阶段。

CMS-concurrent-sweep 第一个子阶段，任务是清除那些没有标记的无用对象并回收内存。后面的参数是耗时，不再多提。

CMS-concurrent-reset 第二个子阶段，作用是重新设置CMS算法内部的数据结构，准备下一个CMS生命周期的使用。

这里再讲一个小知识点，我们上面提到CMS收集器会在老年代内存使用到一定程度时就触发垃圾回收，这是因为CMS收集器的一个缺陷导致的这种设定，也就是无法处理“浮动垃圾”，“浮动垃圾”就是指标记清除阶段用户线程运行产生的垃圾，而这部分对象由于没有做标记处理所以在本次CMS收集中是无法处理的。如果CMS是在老年代空间快用完时才启动垃圾回收，那很可能会导致在并发阶段由于用户线程持续产生垃圾而导致老年代内存不够用而导致“Concurrent Mode Failure”失败，那这时候虚拟机就会启用后备预案，临时启用Serial Old收集器来重新进行老年代的垃圾收集，Serial Old是基于“标记-整理”算法的单线程收集器，这样停顿时间就会很长。这个CMS启动的内存使用阈值可以通过参数 -XX:CMSInitiatiingOccupancyFranction 来设置，默认为68%（这是网上查到的数据），不过这68%应该是JDK1.8之前版本的默认参数，因为上文中初始标记阶段的gc日志分析中显示老年代内存使用到了83%才开始的CMS垃圾收集。我通过在命令行输入 java -XX:+PrintFlagsInitial 命令查看到的本机参数如下，也不知道这-1是什么意思，随机？如果你知道，可以在文章下留言告知，十分感谢！

由于元空间内存不足而引发的Full GC

这里还有一种Full GC日志也比较容易出现，如下：

通过 [Full GC (Metadata GC Threshold) 我们知道这是一次针对整个堆（包括年轻代和老年代）的Full GC，括号中的 Metadata GC Threshold 说明了gc发生的原因，是因为元空间内存不足够而产生扩容导致的GC，同样的我们还可以通过后面的 [CMS: 0K-19938K(1048576K) 看出在老年代内存使用为0的时候就发生了Full GC，所以可以确定不是因为老年代内存不够用而发生的gc。

再后面的 [Metaspace: 20674K-20674K(1069056K)] 表示这次gc前后的元空间（Metaspace）内存变化，元空间的最大容量为1069056K，约等于1G，疑问便来了，最大容量为1G，已使用才20670K，为什么会不够用？

从JDK8开始，方法区采用元空间（Metaspace）的概念来实现，原来的永久代(PermGen)实现被废弃。元空间并不在虚拟机中，而是使用本地内存，默认情况下，元空间的大小仅受本地内存限制。可以通过下面的参数来指定元空间的大小：

还有几个参数也值得我们关注：

所以我们只要根据实际情况将元空间的初始值设置的大一点就可以避免这种Full GC。

程序中调用System.gc()而引发的Full GC

还有一种gc日志，虽然不多见，但也在我这次启动中出现了，如下

[Full GC (System.gc()) 说明这是一次Full GC，是由于调用System.gc()触发的。

后面的 [CMS: 114245K-129265K(536576K) 表示这次gc后老年代内存占用由114245K上涨到了 129265K ，注意，这并不能说明没有对老年代进行回收；再后面的 378366K-129265K(997376K) 表示这次gc后整个堆空间大小缩小到了 129265K ，正好等于老年代的使用量，所以可以推断这次Full GC回收了年轻代的内存，并将存活的对象全部移到了老年代。

为了更清楚的看清这次gc前后各个内存区域的内存占用变化，在启动参数中加入 -XX:+PrintHeapAtGC 参数打印GC前后的堆内存信息，重启idea，同样发生了这种gc，如下：

红框部分的现象跟上面的现象差不多，红框上面是gc前堆中各区域的使用情况，红框下面是gc后堆中各区域的使用情况，可以看出这次gc后新生代确实被清空了（eden、form和to区使用量都为0%），老年代占用内存变大，再反观之前的由于元空间内存不足而发生的Full GC同样也是清空了年轻代，由此可以推论出Full GC会对整个堆进行垃圾回收，并且会将年轻代存活的对象全部转移到老年代。

本文章解读了jdk1.8版本下idea采用CMS收集器时的启动gc日志信息，阅读完这篇文章后能对GC日志有个大体的认识，通过对GC日志的分析可以帮助你更加清晰深入的理解JVM的内存分布，以及垃圾收集的具体细节。不同垃圾收集方案下的gc日志会有所不同，但也都大同小异。

java gc的日志在哪里看？

-verbose.gc开关可显示gc的操作内容。打开它，可以显示最忙和最空闲收集行为发生的时间、收集前后的内存大小、收集需要的时间等。打开- xx:+ printgcdetails开关，可以详细了解gc中的变化。打开-XX: + PrintGCTimeStamps开关，可以了解这些垃圾收集发生的时间，自jvm启动以后以秒计量。最后，通过-xx: + PrintHeapAtGC开关了解堆的更详细的信息。为了了解新域的情况，可以通过-XX:=PrintTenuringDistribution开关了解获得使用期的对象权。

JVM-GC日志查看分析

首先了解关于输出GC日志的参数有以下几种

①GC日志开头的 [GC 和 [Full GC 说明了这次垃圾收集的类型.

② [PSYoungGen 和 [ParOldGen 是指GC发生的区域，分别代表使用 Parallel Scavenge 垃圾收集器的新生代和使用 Parallel old 垃圾收集器的老生代。为什么是这两个垃圾收集器组合呢？因为我的jvm开启的模式是 Server ，而 Server 模式的默认垃圾收集器组合便是这个，在命令行输入 java -version 就可以看到自己的jvm默认开启模式。还有一种是 client 模式，默认组合是 Serial 收集器和 Serial Old 收集器组合。

先了解下 Java memory 划分：

Java memory 主要分 heap memory 和 non-heap memory ，如下图：

⑧默认的，新生代 ( Young ) 与老年代 ( Old ) 的比例的值为 1:2 ( 该值可以通过参数 –XX:NewRatio 来指定 )，即：新生代 ( Young ) = 1/3 的堆空间大小。老年代 ( Old ) = 2/3 的堆空间大小。其中，新生代 ( Young ) 被细分为 Eden 和 两个 Survivor 区域，这两个 Survivor 区域分别被命名为 from 和 to ，以示区分。

⑨ ParOldGen 为老年代，大小为 125952K ，大约为 PSYoungGen 内存大小的 2 倍。 从JDK8开始，永久代( PermGen )的概念被废弃掉了，取而代之的是一个称为 Metaspace (元空间)的存储空间。 Metaspace 与 PermGen 之间最大的区别在于： Metaspace 并不在虚拟机中，而是使用本地内存。

文章参考:

GC日志查看和分析

可以通过在java命令种加入参数来指定对应的gc类型，打印gc日志信息并输出至文件等策略。

GC的日志是以替换的方式()写入的，而不是追加()，如果下次写入到同一个文件中的话，以前的GC内容会被清空。

启动命令:

结果:

也是一次minor gc,但是与前两次的gc原因不一样,这次的gc原因是：[Metadata GC Threshold],Metadata即元数据的意思,我们可以看出这是与虚拟机的元数据区有关系的一次gc;元数据区,在jdk1.8以前又叫永久代,从JDK8开始,永久代(PermGen)的概念被废弃掉了,取而代之的就是这里的称为Metaspace的存储空间;元空间和永久代是虚拟机对方法区这个概念的一个具体实现;对于元空间而言,这一块空间是存在本地内存当中的,因此,默认情况下,元空间的大小仅受本地内存限制,但我们可以通过参数来指定元空间的大小

这里元空间发生gc,说明元空间的内存不够了,到达了阀值;对元空间进行了一次垃圾回收,回收之前是245183K,回收之后是3769K

在元空间gc之后,紧接着发生了一次Full GC,且触发原因也是元空间不足

关于java开启gc日志和java 打印gc日志 影响性能的介绍到此就结束了，不知道你从中找到你需要的信息了吗 ？如果你还想了解更多这方面的信息，记得收藏关注本站。