jvm GC日志解读
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] 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)