jvm GC日志解读

    xiaoxiao2026-01-27  8

    0.产生日志

    0.1 IDE

    运行下面代码会得到gc日志。

    0.2 server

    -Xloggc:../gclogdir/logc.txt   指定gc日志的打印位置,注意必须指定到文件,不能为目录。 当应用重启时,会产生新的gc.log,旧的gc.log自动被重命名为形如 " gc.log.20161103103532"这样的格式。

    1.Parallel Scavenge

    这是一款年轻代GC器。 293.271: [GC [PSYoungGen: 300865K->6577K(310720K)] 392829K->108873K(417472K), 0.0176464 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 每行是一次GC的信息,以本条为例,解读如下。 293.271是本次GC发生的时间,从jvm启动起开始计时,单位为秒。 GC表示这是一次Minor GC(新生代垃圾收集)。 [PSYoungGen: 300865K->6577K(310720K)] 。格式为[PSYoungGen: a->b(c)]. PSYoungGen,表示新生代使用的是多线程垃圾收集器Parallel Scavenge。a为GC前新生代已占用空间,b为GC后新生代已占用空间。新生代又细分为一个Eden区和两个Survivor区,Minor GC之后Eden区为空,b就是Survivor中已被占用的空间。括号里的c表示整个年轻代的大小。 392829K->108873K(417472K),格式为x->y(z)。x表示GC前堆的已占用空间,y表示GC后堆已占用空间,z表示堆的总大小。 由新生代和Java堆占用大小可以算出年老代占用空间,此例中就是417472K-310720K=106752K。 0.0176464 secs表示本次GC所消耗的时间。 [Times: user=0.06 sys=0.00, real=0.01 secs] 提供cpu使用及时间消耗,user是用户态消耗的cpu时间,sys是系统态消耗的cpu时间,real是实际的消耗时间。

    2.Parallel Old

    这是Parallel Scavenge收集器的老年代版本。 0.107: [Full GC (Ergonomics) [PSYoungGen: 1664K->0K(8192K)] [ParOldGen: 8200K->9739K(10240K)] 9864K->9739K(18432K), [Metaspace: 2508K->2508K(1056768K)], 0.0038104 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

    3.CMS

    2016-11-02T10:17:27.849+0800: 48234.161: [GC [1 CMS-initial-mark: 1781099K(2097152K)] 1962885K(4019584K), 0.0530810 secs] [Times: user=0.05 sys=0.00, real=0.05 secs] 2016-11-02T10:17:27.903+0800: 48234.214: [CMS-concurrent-mark-start] 2016-11-02T10:17:30.294+0800: 48236.606: [CMS-concurrent-mark: 2.384/2.391 secs] [Times: user=2.55 sys=0.04, real=2.39 secs] 2016-11-02T10:17:30.294+0800: 48236.606: [CMS-concurrent-preclean-start] 2016-11-02T10:17:30.303+0800: 48236.615: [CMS-concurrent-preclean: 0.009/0.009 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 2016-11-02T10:17:30.303+0800: 48236.615: [CMS-concurrent-abortable-preclean-start] CMS: abort preclean due to time 2016-11-02T10:17:35.525+0800: 48241.836: [CMS-concurrent-abortable-preclean: 5.216/5.221 secs] [Times: user=5.41 sys=0.06, real=5.23 secs] 2016-11-02T10:17:35.526+0800: 48241.837: [GC[YG occupancy: 289491 K (1922432 K)]48241.838: [Rescan (parallel) , 0.0558290 secs]48241.893: [weak refs processing, 0.0063180 secs]48241.900: [class unloading, 0.0323730 secs]48241.932: [scrub symbol & string tables, 0.0297790 secs] [1 CMS-remark: 1781099K(2097152K)] 2070590K(4019584K), 0.1310790 secs] [Times: user=0.26 sys=0.00, real=0.13 secs] 2016-11-02T10:17:35.657+0800: 48241.969: [CMS-concurrent-sweep-start] 2016-11-02T10:17:36.176+0800: 48242.488: [CMS-concurrent-sweep: 0.503/0.519 secs] [Times: user=0.52 sys=0.01, real=0.52 secs] 2016-11-02T10:17:36.176+0800: 48242.488: [CMS-concurrent-reset-start] 2016-11-02T10:17:36.183+0800: 48242.495: [CMS-concurrent-reset: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 一共经历 了4个阶段。需要关注的耗时为 初始标记重新标记,低于0.2秒就没什么问题。 [CMS-xxx   1781099K(2097152K)] 1962885K(4019584K),形如[CMS-xxx   a(b)] c(d) a: old区占用大小 b: old区总大小 c: heap占用大小 d: heap 总大小 [YG occupancy: 289491 K (1922432 K)] ,形如 [YG occupancy: a (b)] a: young区占用大小 b: yong区总大小

    3.1 CMS-initial-mark

    此阶段暂停工作线程,用时0.05秒。

    3.2 CMS-concurrent-mark

    与工作线程并发运行。

    3.3 CMS-remark 

    此阶段暂停工作线程,用时0.13秒。

    3.4 CMS-concurrent-sweep

    与工作线程并发运行。

    4. -XX:+PrintTenuringDistribution -XX:+PrintHeapAtGC

    2016-11-03T14:41:12.877+0800: 14740.294: [GC 14740.295: [ParNew Desired survivor size 178946048 bytes, new threshold 16 (max 20) - age 1: 12374344 bytes, 12374344 total - age 2: 2538032 bytes, 14912376 total - age 3: 2081880 bytes, 16994256 total - age 4: 290784 bytes, 17285040 total - age 5: 787312 bytes, 18072352 total - age 6: 450520 bytes, 18522872 total - age 7: 335016 bytes, 18857888 total - age 8: 661552 bytes, 19519440 total - age 9: 1021048 bytes, 20540488 total - age 10: 130816 bytes, 20671304 total - age 11: 172536 bytes, 20843840 total - age 12: 384968 bytes, 21228808 total - age 13: 556328 bytes, 21785136 total - age 14: 99112 bytes, 21884248 total - age 15: 19091864 bytes, 40976112 total : 3551236K->58224K(3844800K), 0.0259700 secs] 5186234K->1693221K(5941952K), 0.0262100 secs] [Times: user=0.08 sys=0.00, real=0.03 secs] Heap after GC invocations=73 (full 2): par new generation total 3844800K, used 58224K [0x0000000668000000, 0x0000000768000000, 0x0000000768000000) eden space 3495296K, 0% used [0x0000000668000000, 0x0000000668000000, 0x000000073d560000) from space 349504K, 16% used [0x0000000752ab0000, 0x000000075638c030, 0x0000000768000000) to space 349504K, 0% used [0x000000073d560000, 0x000000073d560000, 0x0000000752ab0000) concurrent mark-sweep generation total 2097152K, used 1634997K [0x0000000768000000, 0x00000007e8000000, 0x00000007e8000000) concurrent-mark-sweep perm gen total 274488K, used 197983K [0x00000007e8000000, 0x00000007f8c0e000, 0x0000000800000000) } {Heap before GC invocations=73 (full 2): par new generation total 3844800K, used 3553520K [0x0000000668000000, 0x0000000768000000, 0x0000000768000000) eden space 3495296K, 100% used [0x0000000668000000, 0x000000073d560000, 0x000000073d560000) from space 349504K, 16% used [0x0000000752ab0000, 0x000000075638c030, 0x0000000768000000) to space 349504K, 0% used [0x000000073d560000, 0x000000073d560000, 0x0000000752ab0000) concurrent mark-sweep generation total 2097152K, used 1634997K [0x0000000768000000, 0x00000007e8000000, 0x00000007e8000000) concurrent-mark-sweep perm gen total 274488K, used 197985K [0x00000007e8000000, 0x00000007f8c0e000, 0x0000000800000000) 相关资源:python入门教程(PDF版)
    最新回复(0)