CMS日志

14次阅读

共计 5261 个字符,预计需要花费 14 分钟才能阅读完成。

1. GC 参数配置
-XX:+PrintGC
输出 GC 日志。
-verbose:gc
可以认为 -verbose:gc 是 -XX:+PrintGC 的别名。
-Xloggc:log/gc.log
输出 GC 日志的存储路径。
-XX:+PrintGCDetails
输出 GC 的详细日志。
-XX:+PrintGCDateStamps
输出 GC 的时间戳(以日期的形式)。
-XX:+ExplicitGCInvokesConcurrent
无论什么时候调用系统 GC,都执行 CMS GC,而不是 Full GC。
-XX:+PrintHeapAtGC
在进行 GC 的前后打印出堆的信息。
-Xms512m
设置初始堆的大小。
-Xmx512m
堆分配的最大空间。
-Xmn1024m
设置年轻代大小。
整个 JVM 内存大小 = 年轻代大小 + 年老代大小 + 持久代大小,持久代一般固定大小为 64m,所以增大年轻代后,将会减小年老代大小。此值对系统性能影响较大,Sun 官方推荐配置为整个堆的 3 /8。
-Xss320K
设置每个线程的堆栈大小。
JDK5.0 以后每个线程堆栈大小为 1M,以前每个线程堆栈大小为 256K。根据应用的线程所需内存大小进行调整。在相同物理内存下,减小这个值能生成更多的线程。但是操作系统对一个进程内的线程数还是有限制的,不能无限生成,经验值在 3000~5000 左右。
-XX:+UseConcMarkSweepGC
使用 CMS 收集器,其它类似。
-XX:NewRatio=4
设置年轻代(包括 Eden 和两个 Survivor 区)与年老代的比值(除去持久代)。设置为 4,则年轻代与年老代所占比值为 1:4,年轻代占整个堆栈的 1 /5,默认值是 2 即老年代是新生代内存的 2 倍
-XX:SurvivorRatio=4
设置年轻代中 Eden 区与 Survivor 区的大小比值。设置为 4,则两个 Survivor 区与一个 Eden 区的比值为 2:4,一个 Survivor 区占整个年轻代的 1 /6,默认值为 8。
-XX:MaxPermSize=16m
设置持久代大小为 16m。
-XX:MaxTenuringThreshold=0
设置垃圾最大年龄。如果设置为 0 的话,则年轻代对象不经过 Survivor 区,直接进入年老代。对于年老代比较多的应用,可以提高效率。如果将此值设置为一个较大值,则年轻代对象会在 Survivor 区进行多次复制,这样可以增加对象再年轻代的存活时间,增加在年轻代即被回收的概论。
GC[Allocation Failure] 表示向 young generation(eden) 给新对象申请空间,但是 young generation(eden) 剩余的合适空间不够所需的大小导致的 minor gc。
2. Minor GC: UseParNewGC 回收日志
2018-12-29T14:39:40.102+0800: 3.856: [GC (Allocation Failure) 2018-12-29T14:39:40.102+0800: 3.856: [ParNew: 681600K->72044K(766784K), 0.0977206 secs] 681600K->72044K(4109120K), 0.0978554 secs] [Times: user=0.39
sys=0.06, real=0.10 secs]
2018-12-29T14:39:40.102+0800 本次 gc 触发的时间
3.856 jvm 启动后所经历的秒数
GC (Allocation Failure) 对象分配在新生代但空间不够导致触发一次新生代 gc
ParNew 表示这是新生代 gc 类型, 即 ParNewGC
681600K->72044K(766784K), 0.0977206 secs 触发新生代 gc 时年轻代堆的大小,回收后的年轻代堆的大小,年轻代堆的总大小,该次 gc 回收所耗费的时间
681600K->72044K(4109120K) 回收前堆的总大小,回收后堆的总大小,堆的总大小
3. Major GC: UseConcMarkSweepGC 垃圾收集
CMS 垃圾收集器总共分为 7 个阶段,其中有 2 个结算,即是初始标记和最终标记阶段,是需要暂停用户线程的,其余垃圾收集线程均有用户线程并发执行。
3.1 Phase 1: Initial Mark 初始标记
2018-12-29T14:46:45.247+0800: 429.000: [GC (CMS Initial Mark) [1 CMS-initial-mark: 17305K(3342336K)] 607785K(4109120K), 0.0704856 secs] [Times: user=0.32 sys=0.10, real=0.07 secs]
这是 CMS 中两次 stop-the-world 事件中的一次。它有两个目标:一是标记老年代中所有的 GC Roots;二是标记被年轻代中活着的对象引用的对象。
[1 CMS-initial-mark 收集阶段,开始收集所有的 GC Roots 和直接引用到的对象
17305K(3342336K) 当前老年代的使用情况,老年代可用容量
607785K(4109120K) 当前整个堆的使用情况,整个堆的容量,即是整个堆 – 老年代 = 新生代 (4109120 – 3342336 = 766784)
3.2 Phase 2: Concurrent Mark 并发标记
2018-12-29T14:46:45.317+0800: 429.071: [CMS-concurrent-mark-start]
2018-12-29T14:46:45.326+0800: 429.080: [CMS-concurrent-mark: 0.009/0.009 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
这个阶段会遍历整个老年代并且标记所有存活的对象,从“初始化标记”阶段找到的 GC Roots 开始。并发标记的特点是和应用程序线程同时运行。并不是老年代的所有存活对象都会被标记,因为标记的同时应用程序会改变一些对象的引用等
CMS-concurrent-mark 并发收集阶段,这个阶段会遍历整个年老代并且标记活着的对象
0.009/0.009 secs 展示该阶段持续的时间和时钟时间
3.3 Phase 3: Concurrent Preclean 并发预清除
2018-12-29T14:46:45.326+0800: 429.080: [CMS-concurrent-preclean-start]
2018-12-29T14:46:45.338+0800: 429.092: [CMS-concurrent-preclean: 0.012/0.012 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
这个阶段又是一个并发阶段,和应用线程并行运行,不会中断他们。前一个阶段在并行运行的时候,一些对象的引用已经发生了变化,当这些引用发生变化的时候,JVM 会标记堆的这个区域为 Dirty Card(包含被标记但是改变了的对象,被认为 ”dirty”),这就是 Card Marking。
在 pre-clean 阶段,那些能够从 dirty card 对象到达的对象也会被标记,这个标记做完之后,dirty card 标记就会被清除了
一些必要的清扫工作也会做,还会做一些 final remark 阶段需要的准备工作
CMS-concurrent-preclean 这个阶段负责前一个阶段标记了又发生改变的对象标记
3.4 Phase 4: Concurrent Abortable Preclean 可终止的并发预清理
2018-12-29T14:46:45.338+0800: 429.092: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 2018-12-29T14:46:50.484+0800: 434.238: [CMS-concurrent-abortable-preclean: 4.232/5.146 secs] [Times: user=5.49 sys=0.10, real=5.15 secs]
又一个并发阶段不会停止应用程序线程。这个阶段尝试着去承担 STW 的 Final Remark 阶段足够多的工作。这个阶段持续的时间依赖好多的因素,由于这个阶段是重复的做相同的事情直到发生 aboart 的条件(比如:重复的次数、多少量的工作、持续的时间等等)之一才会停止
CMS-concurrent-abortable-preclean 可终止的并发预清理
这个阶段很大程度的影响着即将来临的 Final Remark 的停顿,有相当一部分重要的 configuration options 和 失败的模式
3.5 Phase 5: Final Remark 最终标记
2018-12-29T14:46:50.485+0800: 434.239: [GC (CMS Final Remark) [YG occupancy: 632074 K (766784 K)]2018-12-29T14:46:50.485+0800: 434.239: [Rescan (parallel) , 0.0791637 secs]2018-12-29T14:46:50.564+0800: 434.318:
[weak refs processing, 0.0001243 secs]2018-12-29T14:46:50.565+0800: 434.318: [class unloading, 0.0409380 secs]2018-12-29T14:46:50.605+0800: 434.359: [scrub symbol table, 0.0136356 secs]2018-12-29T14:46:50.619+08
00: 434.373: [scrub string table, 0.0015586 secs][1 CMS-remark: 17305K(3342336K)] 649380K(4109120K), 0.1370772 secs] [Times: user=0.46 sys=0.06, real=0.13 secs]
这个阶段是 CMS 中第二个并且是最后一个 STW 的阶段。该阶段的任务是完成标记整个年老代的所有的存活对象。由于之前的预处理是并发的,它可能跟不上应用程序改变的速度,这个时候,STW 是非常需要的来完成这个严酷考验的阶段。
通常 CMS 尽量运行 Final Remark 阶段在年轻代是足够干净的时候,目的是消除紧接着的连续的几个 STW 阶段
CMS Final Remark 收集阶段,这个阶段会标记老年代全部的存活对象,包括那些在并发标记阶段更改的或者新创建的引用对象
YG occupancy: 632074 K (766784 K) 年轻代当前占用的情况和容量
Rescan (parallel) 这个阶段在应用停止的阶段完成存活对象的标记工作
weak refs processing 第一个子阶段,随着这个阶段的进行处理弱引用
class unloading 第二个子阶段, 类的卸载
scrub symbol table 最后一个子阶段, 清理字符引用等
1 CMS-remark: 17305K(3342336K) 在这个阶段之后老年代占有的内存大小和老年代的容量
649380K(4109120K) 在这个阶段之后整个堆的内存大小和整个堆的容量
通过以上 5 个阶段的标记,老年代所有存活的对象已经被标记并且现在要通过 Garbage Collector 采用清扫的方式回收那些不能用的对象了
3.6 Phase 6: Concurrent Sweep 并发清除
2018-12-29T14:46:50.622+0800: 434.376: [CMS-concurrent-sweep-start]
2018-12-29T14:46:50.635+0800: 434.388: [CMS-concurrent-sweep: 0.012/0.012 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
和应用线程同时进行,不需要 STW。这个阶段的目的就是移除那些不用的对象,回收他们占用的空间并且为将来使用。
CMS-concurrent-sweep 这个阶段主要是清除那些没有标记的对象并且回收空间
3.7 Phase 7: Concurrent Reset 并发重置
2018-12-29T14:46:50.635+0800: 434.388: [CMS-concurrent-reset-start]
2018-12-29T14:46:50.651+0800: 434.405: [CMS-concurrent-reset: 0.016/0.016 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
这个阶段并发执行,重新设置 CMS 算法内部的数据结构,准备下一个 CMS 生命周期的使用
CMS-concurrent-reset 这个阶段重新设置 CMS 算法内部的数据结构,为下一个收集阶段做准备
JVM 调优——之 CMS GC 日志分析

正文完
 0