java中jvm的gc日志解析,jvm如何查看gc日志

发布时间：2022-11-23

本文目录一览：

  1. [理解CMS GC日志](#理解CMS GC日志)
  2. [JVM GC 日志详解](#JVM GC 日志详解)
  3. [jrockit的jvm的 gc日志输出能详细到什么程度](#jrockit的jvm的 gc日志输出能详细到什么程度)
  4. [jvm GC日志 相关参数](#jvm GC日志 相关参数)
  5. eclipse设置查看GC日志和如何理解GC日志
  6. [JVM性能调优（2） —— 内存设置和查看GC日志](#JVM性能调优（2） —— 内存设置和查看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 World，下面统称为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阶段足够多的工作，由于这个阶段是重复的做相同的事情直到发生abort的条件（比如：重复的次数、多少量的工作、持续的时间等等）之一才会停止。这个阶段很大程度的影响着即将来临的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:CMSInitiatingOccupancyFraction 来设置，默认为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、from和to区使用量都为0%），老年代占用内存变大，再反观之前的由于元空间内存不足而发生的Full GC同样也是清空了年轻代，由此可以推论出Full GC会对整个堆进行垃圾回收，并且会将年轻代存活的对象全部转移到老年代。 本文章解读了JDK1.8版本下IDEA采用CMS收集器时的启动GC日志信息，阅读完这篇文章后能对GC日志有个大体的认识，通过对GC日志的分析可以帮助你更加清晰深入的理解JVM的内存分布，以及垃圾收集的具体细节。不同垃圾收集方案下的GC日志会有所不同，但也都大同小异。

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
  6. GC 表示是一次YGC（Young GC）
  7. Allocation Failure 表示是失败的类型
  8. PSYoungGen 表示年轻代大小
  9. 53248K-2176K 表示年轻代占用从53248K降为2176K
  10. 59392K 表示年轻代的大小
  11. 58161K-7161K 表示整个堆占用从53248K降为2176K
  12. 256000K 表示整个堆的大小
  13. 0.0039189 secs 表示这次GC总计所用的时间
  14. [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相等
  15. Heap before GC invocations=1 表示是第1次GC调用之前的堆内存状况
  16. {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] 会STW（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] 并发重置所用结束，所用的时间。 参考：

jrockit的jvm的 gc日志输出能详细到什么程度

可以通过在Java命令中加入参数来指定对应的GC类型，打印GC日志信息并输出至文件等策略。 GC的日志是以替换的方式写入的，而不是追加，如果下次写入到同一个文件中的话，以前的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 日志文件的输出路径 这里使用如下的参数来进行日志的打印： -XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:./gclogs 对于新生代回收的一行日志，其基本内容如下：
2014-07-18T16:02:17.606+0800: 611.633: [GC 611.633: [DefNew: 843458K-2K(948864K), 0.0059180 secs] 2186589K-1343132K(3057292K), 0.0059490 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

其含义大概如下：

  • 2014-07-18T16:02:17.606+0800（当前时间戳）
  • 611.633（时间戳）: [GC（表示Young GC）
  • 611.633: [DefNew（单线程Serial年轻代GC）: 843458K（年轻代垃圾回收前的大小）-2K（年轻代回收后的大小）(948864K（年轻代总大小）), 0.0059180 secs（本次回收的时间）]
  • 2186589K（整个堆回收前的大小）-1343132K（整个堆回收后的大小）(3057292K（堆总大小）), 0.0059490 secs（回收时间）]
  • [Times: user=0.00（用户耗时） sys=0.00（系统耗时）, real=0.00 secs（实际耗时）] 老年代回收的日志如下：
2014-07-18T16:19:16.794+0800: 1630.821: [GC 1630.821: [DefNew: 1005567K-111679K(1005568K), 0.9152360 secs]1631.736: [Tenured:
2573912K-1340650K(2574068K), 1.8511050 secs] 3122548K-1340650K(3579636K), [Perm : 17882K-17882K(21248K)], 2.7854350 secs] [Times: user=2.57 sys=0.22, real=2.79 secs]

GC日志中的最后貌似是系统运行完成前的快照：

Heap
def new generation total 1005568K, used 111158K [0x00000006fae00000, 0x000000073f110000, 0x0000000750350000)
eden space 893888K, 12% used [0x00000006fae00000, 0x0000000701710e90, 0x00000007316f0000)
from space 111680K, 3% used [0x0000000738400000, 0x000000073877c9b0, 0x000000073f110000)
to space 111680K, 0% used [0x00000007316f0000, 0x00000007316f0000, 0x0000000738400000)
tenured generation total 2234420K, used 1347671K [0x0000000750350000, 0x00000007d895d000, 0x00000007fae00000)
the space 2234420K, 60% used [0x0000000750350000, 0x00000007a2765cb8, 0x00000007a2765e00, 0x00000007d895d000)
compacting perm gen total 21248K, used 17994K [0x00000007fae00000, 0x00000007fc2c0000, 0x0000000800000000)
the space 21248K, 84% used [0x00000007fae00000, 0x00000007fbf92a50, 0x00000007fbf92c00, 0x00000007fc2c0000)
No shared spaces configured.

jvm GC日志 相关参数

  • -XX:+PrintGC 最简单的 GC 参数，会打印 GC 前后堆空间使用情况以及 GC 花费的时间
  • -XX:+PrintGCDetails 会打印 YoungGC、FullGC 前后堆（新生代、老年代、永久区）的使用情况以及 GC 时用户态 CPU 耗时及系统 CPU 耗时及 GC 实际经历的时间
  • -XX:+PrintGCHeapAtGC 比 -XX:+PrintGCDetails 更全面的堆信息
  • -XX:+PrintGCTimeStamps 输出发生 GC 的时间，输出时间为虚拟机启动后的时间偏移量
  • -XX:+PrintGCApplicationConcurrentTime 打印应用程序执行的时间
  • -XX:+PrintGCApplicationStoppedTime 打印应用程序由于 GC 停顿的时间
  • -XX:+PrintReferenceGC 打印系统中软引用、弱引用、虚引用
  • -Xloggc:log/gc.log 指定 GC 日志输出位置

eclipse设置查看GC日志和如何理解GC日志

  1. Run as - Run configurations - Java应用名 - arguments - VM arguments，加入JVM参数就行
  2. 测试代码
package cn.erong.test;
public class Jtest {
    private static final int _1M = 1024*1024;
    public static void main(String[] args) {
        byte[] allocation1, allocation2, allocation3, allocation4;
        allocation1 = new byte[_1M/4];
        allocation2 = new byte[_1M/4];
        allocation3 = new byte[4*_1M];
        allocation4 = new byte[4*_1M];
        allocation4 = null;
        allocation4 = new byte[4*_1M];
    }
}
  1. 测试看下，在VM arguments 中加入：
-Xms20m --JVM堆的最小值
-Xmx20m --JVM堆的最大值
-XX:+PrintGCTimeStamps --打印出GC的时间信息
-XX:+PrintGCDetails --打印出GC的详细信息
-verbose:gc --开启GC日志
-Xloggc:d:/gc.log --GC日志的存放位置
-Xmn10M --新生代内存区域的大小
-XX:SurvivorRatio=8 --新生代内存区域中Eden和Survivor的比例
  1. Run 看下日志，到D盘找到 gc.log，如下：
Java HotSpot(TM) Client VM (25.151-b12) for windows-x86 JRE (1.8.0_151-b12), built on Sep 5 2017 19:31:49 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 3567372k(982296k free), swap 7133056k(3042564k free)
CommandLine flags: -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:MaxNewSize=10485760 -XX:NewSize=10485760 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:-UseLargePagesIndividualAllocation
0.091: [GC (Allocation Failure) 0.091: [DefNew: 5427K-995K(9216K), 0.0036445 secs] 5427K-5091K(19456K), 0.0038098 secs] [Times: user=0.00 sys=0.02, real=0.00 secs]
0.095: [GC (Allocation Failure) 0.095: [DefNew: 5091K-0K(9216K), 0.0012412 secs] 9187K-5090K(19456K), 0.0012908 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
Heap
def new generation   total 9216K, used 4260K [0x04000000, 0x04a00000, 0x04a00000)
  eden space 8192K,  52% used [0x04000000, 0x044290e8, 0x04800000)
 from space 1024K,   0% used [0x04800000, 0x04800000, 0x04900000)
 to   space 1024K,   0% used [0x04900000, 0x04900000, 0x04a00000)
tenured generation   total 10240K, used 5090K [0x04a00000, 0x05400000, 0x05400000)
  the space 10240K,  49% used [0x04a00000, 0x04ef8ac0, 0x04ef8c00, 0x05400000)
Metaspace       used 84K, capacity 2242K, committed 2368K, reserved 4480K

JVM性能调优（2） —— 内存设置和查看GC日志

  1. JVM内存分配有如下一些参数： 一般 -Xms 和 -Xmx 设置一样的大小，-XX:MetaspaceSize 和 -XX:MaxMetaspaceSize 设置一样的大小。-Xms 等价于 -XX:InitialHeapSize，-Xmx 等价于 -XX:MaxHeapSize；-Xmn 等价于 -XX:MaxNewSize。
  2. 在IDEA中可以按照如下方式设置JVM参数：
  3. 命令行启动时可以按照如下格式设置： 
    java -Xms20m -Xmx20m -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -verbose:gc -Xloggc:d:/gc.log -Xmn10M -XX:SurvivorRatio=8 -jar your_app.jar
  4. 设置GC参数： 可以在启动时加上如下参数来查看GC日志： 
    -XX:+PrintGC
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintGCDateStamps
-XX:+PrintHeapAtGC
-Xloggc:./gc.log
    例如，我在IDEA中添加了如下JVM启动参数： 
    -Xms20m -Xmx20m -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -verbose:gc -Xloggc:d:/gc.log -Xmn10M -XX:SurvivorRatio=8
    启动程序之后打印出了如下的一些日志： 
    Java HotSpot(TM) Client VM (25.151-b12) for windows-x86 JRE (1.8.0_151-b12), built on Sep 5 2017 19:31:49 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 3567372k(982296k free), swap 7133056k(3042564k free)
CommandLine flags: -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:MaxNewSize=10485760 -XX:NewSize=10485760 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:-UseLargePagesIndividualAllocation
0.091: [GC (Allocation Failure) 0.091: [DefNew: 5427K-995K(9216K), 0.0036445 secs] 5427K-5091K(19456K), 0.0038098 secs] [Times: user=0.00 sys=0.02, real=0.00 secs]
0.095: [GC (Allocation Failure) 0.095: [DefNew: 5091K-0K(9216K), 0.0012412 secs] 9187K-5090K(19456K), 0.0012908 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
  5. 查看默认参数： 如果要查看JVM的默认参数，就可以通过给JVM加打印GC日志的参数，就可以在GC日志中看到JVM的默认参数了。 还可以在启动参数中添加 -XX:+PrintFlagsFinal 参数，将会打印系统的所有参数，就可以看到自己配置的参数或系统的默认参数了：
  6. GC日志： 之后的日志就是每次垃圾回收时产生的日志，每行日志说明了这次GC的执行情况，例如第四行GC日志： 
    2020-09-25T13:00:41.631+0800: 4.013: [GC (Allocation Failure) [PSYoungGen: 419840K->20541K(472064K)] 419840K->20573K(996352K), 0.0118345 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
    详细内容如下：
    • 2020-09-25T13:00:41.631+0800：GC发生的时间点。
    • 4.013：系统运行多久之后发生的GC，单位秒，这里就是系统运行 4.013 秒后发生了一次GC。
    • GC (Allocation Failure)：说明了触发GC的原因，这里是指对象分配失败导致的GC。
    • PSYoungGen：指触发的是年轻代的垃圾回收，使用的是 Parallel Scavenge 垃圾回收器。
    • 419840K-20541K：对年轻代执行了一次GC，GC之前年轻代使用了 419840K，GC之后有 20541K 的对象活下来了。
    • (472064K)：年轻代可用空间是 472064K，即 461M，为什么是461M呢？因为新生代大小为 512M，Eden 区占 409.6M，两块 Survivor 区各占 51.2M，所以年轻代的可用空间为 Eden+1个Survivor的大小，即 460.8M，约为 461M。
    • 419840K-20573K：GC前整个堆内存使用了 419840K，GC之后堆内存使用了 20573K。
    • (996352K)：整个堆的大小是 996352K，即 973M，其实就是年轻代的 461M + 老年代的 512M
    • 0.0118345 secs：本次GC耗费的时间
    • [Times: user=0.00 sys=0.00, real=0.01 secs]：本次GC耗费的时间
  7. JVM退出时的GC情况： 程序结束运行后，还会打印一些日志，就是第12行之后的日志，这部分展示的是当前堆内存的使用情况： 
    Heap
def new generation   total 9216K, used 4260K [0x04000000, 0x04a00000, 0x04a00000)
  eden space 8192K,  52% used [0x04000000, 0x044290e8, 0x04800000)
 from space 1024K,   0% used [0x04800000, 0x04800000, 0x04900000)
  to   space 1024K,   0% used [0x04900000, 0x04900000, 0x04a00000)
tenured generation   total 10240K, used 5090K [0x04a00000, 0x05400000, 0x05400000)
  the space 10240K,  49% used [0x04a00000, 0x04ef8ac0, 0x04ef8c00, 0x05400000)
Metaspace       used 84K, capacity 2242K, committed 2368K, reserved 4480K
推荐文章