打印gc日志:
- -XX:+PrintGCDetails
- 可以自动开启-XX:+PrintGC参数
- -XX:+PrintHeapAtGC
- 打印gc前后堆中各区使用的情况
- -XX:+PrintTenuringDistribution
- 打印本次gc中对象的晋升年龄阈值及Survivor区中各个年龄段对象的分布
- -XX:+PrintGCDateStamps
- 打印gc时的日期
- -XX:+PrintGCTimeStamps
- 打印gc时的时间戳
- -Xloggc:logs/gc.log
- 指定gc日志存储位置
Young GC
# --- Young GC start ---
# 之前young gc次数、之前full gc次数
{Heap before GC invocations=124398 (full 12):
# 年轻代使用情况: 总空间、已使用空间、地址范围[low、current、upper]
par new generation total 943744K, used 854618K [0x00000006c3000000, 0x0000000703000000, 0x0000000703000000)
eden space 838912K, 100% used [0x00000006c3000000, 0x00000006f6340000, 0x00000006f6340000)
from space 104832K, 14% used [0x00000006f6340000, 0x00000006f7296838, 0x00000006fc9a0000)
to space 104832K, 0% used [0x00000006fc9a0000, 0x00000006fc9a0000, 0x0000000703000000)
# 老年代使用情况
concurrent mark-sweep generation total 3096576K, used 2848828K [0x0000000703000000, 0x00000007c0000000, 0x00000007c0000000)
# 元数据区
Metaspace used 198589K, capacity 216656K, committed 216804K, reserved 1239040K
class space used 23380K, capacity 26312K, committed 26340K, reserved 1048576K
# 年轻代分配内存失败,说明年轻代没有足够的空间来给对象分配,此时就会进行Young gc
# GC GC的类型,GC表示Young gc
# (Allocation Failure) GC发生的原因
# ParNew 年轻代使用ParNew收集器
2017-09-07T00:37:50.128+0800: 1600470.391: [GC (Allocation Failure) 1600470.391: [ParNew
# Desired survivor size
# 期望survivor区使用的大小,默认值为survivor区的一半。
# 计算方式:-XX:TargetSurvivorRatio 设定survivor区的目标使用率,默认50
#
# new threshold
# 新的晋升年龄阈值,即本次gc中的晋升年龄阈值。
# 计算方式:survivor中age<=n的对象所占内存大于Desired survivor size 且 n小于max时,阈值为n,否则为max。
#
# max
# 晋升年龄阈值最大值
# 计算方式:-XX:MaxTenuringThreshold
#
# age行:对象的年龄:survivor中当前年龄对象所占内存的大小, survivor中年龄小于等于当前年龄对象所占内存的大小
#
Desired survivor size 53673984 bytes, new threshold 6 (max 6)
- age 1: 2582656 bytes, 2582656 total
- age 2: 7816304 bytes, 10398960 total
- age 3: 170816 bytes, 10569776 total
- age 4: 80608 bytes, 10650384 total
- age 5: 256672 bytes, 10907056 total
- age 6: 180880 bytes, 11087936 total
# gc前年轻代已使用的容量->gc后年轻代已使用容量(年轻代的总容量), 年轻代gc花费的时间 ]
# gc前堆已使用的容量->gc后堆已使用容量(堆的总容量), 堆gc花费的时间 ]
# user 用户态消耗的CPU时间
# sys 内核态消耗的CPU时间
# real gc从开始到结束所经过的墙钟时间
# 1>墙钟时间包括CPU时间、各种非运算的等待耗时:等待磁盘I/O、线程阻塞等。
# 2>当系统是多CPU或多核的话,多线程操作会叠加这些CPU时间,故我们经常可以看到user或sys大于real的情况。
: 854618K->16513K(943744K), 0.0186958 secs] 3703446K->2865514K(4040320K), 0.0192603 secs] [Times: user=0.06 sys=0.02, real=0.02 secs]
# GC后堆的使用情况
Heap after GC invocations=124399 (full 12):
par new generation total 943744K, used 16513K [0x00000006c3000000, 0x0000000703000000, 0x0000000703000000)
eden space 838912K, 0% used [0x00000006c3000000, 0x00000006c3000000, 0x00000006f6340000)
from space 104832K, 15% used [0x00000006fc9a0000, 0x00000006fd9c04c8, 0x0000000703000000)
to space 104832K, 0% used [0x00000006f6340000, 0x00000006f6340000, 0x00000006fc9a0000)
concurrent mark-sweep generation total 3096576K, used 2849001K [0x0000000703000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 198589K, capacity 216656K, committed 216804K, reserved 1239040K
class space used 23380K, capacity 26312K, committed 26340K, reserved 1048576K
}
# --- Young GC end ---
Full GC
# --- Full GC start ---
# GC (CMS Initial Mark) 表示CMS GC(full gc的一种)
#
# CMS-initial-mark 初始标记:老年代已使用的容量(老年代总容量) 堆已使用的容量(堆的总容量)
2017-09-07T00:37:50.167+0800: 1600470.430: [GC (CMS Initial Mark) [1 CMS-initial-mark: 2849001K(3096576K)] 2895790K(4040320K), 0.0280525 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
# CMS-concurrent-mark 并发标记:0.510/0.510 secs 并发标记花费的cpu时间/并发标记花费的总时间
2017-09-07T00:37:50.196+0800: 1600470.459: [CMS-concurrent-mark-start]
2017-09-07T00:37:50.705+0800: 1600470.968: [CMS-concurrent-mark: 0.510/0.510 secs] [Times: user=0.74 sys=0.00, real=0.51 secs]
# CMS-concurrent-preclean 并发预清理
2017-09-07T00:37:50.705+0800: 1600470.968: [CMS-concurrent-preclean-start]
2017-09-07T00:37:50.727+0800: 1600470.990: [CMS-concurrent-preclean: 0.021/0.021 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
# CMS-concurrent-abortable-preclean 并发可终止预清理
2017-09-07T00:37:50.727+0800: 1600470.990: [CMS-concurrent-abortable-preclean-start]
# Young GC start
{Heap before GC invocations=124399 (full 13):
par new generation total 943744K, used 855425K [0x00000006c3000000, 0x0000000703000000, 0x0000000703000000)
eden space 838912K, 100% used [0x00000006c3000000, 0x00000006f6340000, 0x00000006f6340000)
from space 104832K, 15% used [0x00000006fc9a0000, 0x00000006fd9c04c8, 0x0000000703000000)
to space 104832K, 0% used [0x00000006f6340000, 0x00000006f6340000, 0x00000006fc9a0000)
concurrent mark-sweep generation total 3096576K, used 2849001K [0x0000000703000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 198589K, capacity 216656K, committed 216804K, reserved 1239040K
class space used 23380K, capacity 26312K, committed 26340K, reserved 1048576K
2017-09-07T00:37:53.257+0800: 1600473.520: [GC (Allocation Failure) 1600473.520: [ParNew
Desired survivor size 53673984 bytes, new threshold 6 (max 6)
- age 1: 10813272 bytes, 10813272 total
- age 2: 76576 bytes, 10889848 total
- age 3: 67392 bytes, 10957240 total
- age 4: 168624 bytes, 11125864 total
- age 5: 80560 bytes, 11206424 total
- age 6: 256552 bytes, 11462976 total
: 855425K->13593K(943744K), 0.0177559 secs] 3704426K->2862772K(4040320K), 0.0182244 secs] [Times: user=0.07 sys=0.00, real=0.02 secs]
Heap after GC invocations=124400 (full 13):
par new generation total 943744K, used 13593K [0x00000006c3000000, 0x0000000703000000, 0x0000000703000000)
eden space 838912K, 0% used [0x00000006c3000000, 0x00000006c3000000, 0x00000006f6340000)
from space 104832K, 12% used [0x00000006f6340000, 0x00000006f70865e8, 0x00000006fc9a0000)
to space 104832K, 0% used [0x00000006fc9a0000, 0x00000006fc9a0000, 0x0000000703000000)
concurrent mark-sweep generation total 3096576K, used 2849178K [0x0000000703000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 198589K, capacity 216656K, committed 216804K, reserved 1239040K
class space used 23380K, capacity 26312K, committed 26340K, reserved 1048576K
}
# Young GC end
2017-09-07T00:37:55.522+0800: 1600475.785: [CMS-concurrent-abortable-preclean: 4.771/4.795 secs] [Times: user=7.07 sys=0.19, real=4.80 secs]
# CMS-remark 重新标记
2017-09-07T00:37:55.524+0800: 1600475.788: [GC (CMS Final Remark) [YG occupancy: 448452 K (943744 K)]
1600475.788: [Rescan (parallel) , 0.0851724 secs]
1600475.873: [weak refs processing, 0.3228541 secs]
1600476.196: [class unloading, 0.1102851 secs]
1600476.306: [scrub symbol table, 0.0431544 secs]
1600476.349: [scrub string table, 0.0032872 secs][1 CMS-remark: 2849178K(3096576K)] 3297631K(4040320K), 0.5951137 secs] [Times: user=0.85 sys=0.00, real=0.59 secs]
# CMS-concurrent-sweep 并发清除
2017-09-07T00:37:56.120+0800: 1600476.383: [CMS-concurrent-sweep-start]
# Young GC start
{Heap before GC invocations=124400 (full 13):
par new generation total 943744K, used 852505K [0x00000006c3000000, 0x0000000703000000, 0x0000000703000000)
eden space 838912K, 100% used [0x00000006c3000000, 0x00000006f6340000, 0x00000006f6340000)
from space 104832K, 12% used [0x00000006f6340000, 0x00000006f70865e8, 0x00000006fc9a0000)
to space 104832K, 0% used [0x00000006fc9a0000, 0x00000006fc9a0000, 0x0000000703000000)
concurrent mark-sweep generation total 3096576K, used 1262591K [0x0000000703000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 198589K, capacity 216656K, committed 216804K, reserved 1239040K
class space used 23380K, capacity 26312K, committed 26340K, reserved 1048576K
2017-09-07T00:37:57.483+0800: 1600477.746: [GC (Allocation Failure) 1600477.746: [ParNew
Desired survivor size 53673984 bytes, new threshold 6 (max 6)
- age 1: 10809912 bytes, 10809912 total
- age 2: 74840 bytes, 10884752 total
- age 3: 72080 bytes, 10956832 total
- age 4: 63064 bytes, 11019896 total
- age 5: 168160 bytes, 11188056 total
- age 6: 80128 bytes, 11268184 total
: 852505K->13891K(943744K), 0.0253010 secs] 2115097K->1276734K(4040320K), 0.0257613 secs] [Times: user=0.08 sys=0.02, real=0.02 secs]
Heap after GC invocations=124401 (full 13):
par new generation total 943744K, used 13891K [0x00000006c3000000, 0x0000000703000000, 0x0000000703000000)
eden space 838912K, 0% used [0x00000006c3000000, 0x00000006c3000000, 0x00000006f6340000)
from space 104832K, 13% used [0x00000006fc9a0000, 0x00000006fd730c68, 0x0000000703000000)
to space 104832K, 0% used [0x00000006f6340000, 0x00000006f6340000, 0x00000006fc9a0000)
concurrent mark-sweep generation total 3096576K, used 1262843K [0x0000000703000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 198589K, capacity 216656K, committed 216804K, reserved 1239040K
class space used 23380K, capacity 26312K, committed 26340K, reserved 1048576K
}
# Young GC end
2017-09-07T00:37:58.004+0800: 1600478.268: [CMS-concurrent-sweep: 1.853/1.884 secs] [Times: user=2.96 sys=0.42, real=1.89 secs]
# CMS-concurrent-reset 并发重设
2017-09-07T00:37:58.018+0800: 1600478.281: [CMS-concurrent-reset-start]
2017-09-07T00:37:58.024+0800: 1600478.287: [CMS-concurrent-reset: 0.006/0.006 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
# --- Full GC end ---
日志分析:
原始日志:
Young GC + Full GC
# --- Young GC start ---
{Heap before GC invocations=124398 (full 12):
par new generation total 943744K, used 854618K [0x00000006c3000000, 0x0000000703000000, 0x0000000703000000)
eden space 838912K, 100% used [0x00000006c3000000, 0x00000006f6340000, 0x00000006f6340000)
from space 104832K, 14% used [0x00000006f6340000, 0x00000006f7296838, 0x00000006fc9a0000)
to space 104832K, 0% used [0x00000006fc9a0000, 0x00000006fc9a0000, 0x0000000703000000)
concurrent mark-sweep generation total 3096576K, used 2848828K [0x0000000703000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 198589K, capacity 216656K, committed 216804K, reserved 1239040K
class space used 23380K, capacity 26312K, committed 26340K, reserved 1048576K
2017-09-07T00:37:50.128+0800: 1600470.391: [GC (Allocation Failure) 1600470.391: [ParNew
Desired survivor size 53673984 bytes, new threshold 6 (max 6)
- age 1: 2582656 bytes, 2582656 total
- age 2: 7816304 bytes, 10398960 total
- age 3: 170816 bytes, 10569776 total
- age 4: 80608 bytes, 10650384 total
- age 5: 256672 bytes, 10907056 total
- age 6: 180880 bytes, 11087936 total
: 854618K->16513K(943744K), 0.0186958 secs] 3703446K->2865514K(4040320K), 0.0192603 secs] [Times: user=0.06 sys=0.02, real=0.02 secs]
Heap after GC invocations=124399 (full 12):
par new generation total 943744K, used 16513K [0x00000006c3000000, 0x0000000703000000, 0x0000000703000000)
eden space 838912K, 0% used [0x00000006c3000000, 0x00000006c3000000, 0x00000006f6340000)
from space 104832K, 15% used [0x00000006fc9a0000, 0x00000006fd9c04c8, 0x0000000703000000)
to space 104832K, 0% used [0x00000006f6340000, 0x00000006f6340000, 0x00000006fc9a0000)
concurrent mark-sweep generation total 3096576K, used 2849001K [0x0000000703000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 198589K, capacity 216656K, committed 216804K, reserved 1239040K
class space used 23380K, capacity 26312K, committed 26340K, reserved 1048576K
}
# --- Young GC end ---
# --- Full GC start ---
2017-09-07T00:37:50.167+0800: 1600470.430: [GC (CMS Initial Mark) [1 CMS-initial-mark: 2849001K(3096576K)] 2895790K(4040320K), 0.0280525 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
2017-09-07T00:37:50.196+0800: 1600470.459: [CMS-concurrent-mark-start]
2017-09-07T00:37:50.705+0800: 1600470.968: [CMS-concurrent-mark: 0.510/0.510 secs] [Times: user=0.74 sys=0.00, real=0.51 secs]
2017-09-07T00:37:50.705+0800: 1600470.968: [CMS-concurrent-preclean-start]
2017-09-07T00:37:50.727+0800: 1600470.990: [CMS-concurrent-preclean: 0.021/0.021 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
2017-09-07T00:37:50.727+0800: 1600470.990: [CMS-concurrent-abortable-preclean-start]
{Heap before GC invocations=124399 (full 13):
par new generation total 943744K, used 855425K [0x00000006c3000000, 0x0000000703000000, 0x0000000703000000)
eden space 838912K, 100% used [0x00000006c3000000, 0x00000006f6340000, 0x00000006f6340000)
from space 104832K, 15% used [0x00000006fc9a0000, 0x00000006fd9c04c8, 0x0000000703000000)
to space 104832K, 0% used [0x00000006f6340000, 0x00000006f6340000, 0x00000006fc9a0000)
concurrent mark-sweep generation total 3096576K, used 2849001K [0x0000000703000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 198589K, capacity 216656K, committed 216804K, reserved 1239040K
class space used 23380K, capacity 26312K, committed 26340K, reserved 1048576K
2017-09-07T00:37:53.257+0800: 1600473.520: [GC (Allocation Failure) 1600473.520: [ParNew
Desired survivor size 53673984 bytes, new threshold 6 (max 6)
- age 1: 10813272 bytes, 10813272 total
- age 2: 76576 bytes, 10889848 total
- age 3: 67392 bytes, 10957240 total
- age 4: 168624 bytes, 11125864 total
- age 5: 80560 bytes, 11206424 total
- age 6: 256552 bytes, 11462976 total
: 855425K->13593K(943744K), 0.0177559 secs] 3704426K->2862772K(4040320K), 0.0182244 secs] [Times: user=0.07 sys=0.00, real=0.02 secs]
Heap after GC invocations=124400 (full 13):
par new generation total 943744K, used 13593K [0x00000006c3000000, 0x0000000703000000, 0x0000000703000000)
eden space 838912K, 0% used [0x00000006c3000000, 0x00000006c3000000, 0x00000006f6340000)
from space 104832K, 12% used [0x00000006f6340000, 0x00000006f70865e8, 0x00000006fc9a0000)
to space 104832K, 0% used [0x00000006fc9a0000, 0x00000006fc9a0000, 0x0000000703000000)
concurrent mark-sweep generation total 3096576K, used 2849178K [0x0000000703000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 198589K, capacity 216656K, committed 216804K, reserved 1239040K
class space used 23380K, capacity 26312K, committed 26340K, reserved 1048576K
}
2017-09-07T00:37:55.522+0800: 1600475.785: [CMS-concurrent-abortable-preclean: 4.771/4.795 secs] [Times: user=7.07 sys=0.19, real=4.80 secs]
2017-09-07T00:37:55.524+0800: 1600475.788: [GC (CMS Final Remark) [YG occupancy: 448452 K (943744 K)]1600475.788: [Rescan (parallel) , 0.0851724 secs]1600475.873: [weak refs processing, 0.3228541 secs]1600476.196: [class unloading, 0.1102851 secs]1600476.306: [scrub symbol table, 0.0431544 secs]1600476.349: [scrub string table, 0.0032872 secs][1 CMS-remark: 2849178K(3096576K)] 3297631K(4040320K), 0.5951137 secs] [Times: user=0.85 sys=0.00, real=0.59 secs]
2017-09-07T00:37:56.120+0800: 1600476.383: [CMS-concurrent-sweep-start]
{Heap before GC invocations=124400 (full 13):
par new generation total 943744K, used 852505K [0x00000006c3000000, 0x0000000703000000, 0x0000000703000000)
eden space 838912K, 100% used [0x00000006c3000000, 0x00000006f6340000, 0x00000006f6340000)
from space 104832K, 12% used [0x00000006f6340000, 0x00000006f70865e8, 0x00000006fc9a0000)
to space 104832K, 0% used [0x00000006fc9a0000, 0x00000006fc9a0000, 0x0000000703000000)
concurrent mark-sweep generation total 3096576K, used 1262591K [0x0000000703000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 198589K, capacity 216656K, committed 216804K, reserved 1239040K
class space used 23380K, capacity 26312K, committed 26340K, reserved 1048576K
2017-09-07T00:37:57.483+0800: 1600477.746: [GC (Allocation Failure) 1600477.746: [ParNew
Desired survivor size 53673984 bytes, new threshold 6 (max 6)
- age 1: 10809912 bytes, 10809912 total
- age 2: 74840 bytes, 10884752 total
- age 3: 72080 bytes, 10956832 total
- age 4: 63064 bytes, 11019896 total
- age 5: 168160 bytes, 11188056 total
- age 6: 80128 bytes, 11268184 total
: 852505K->13891K(943744K), 0.0253010 secs] 2115097K->1276734K(4040320K), 0.0257613 secs] [Times: user=0.08 sys=0.02, real=0.02 secs]
Heap after GC invocations=124401 (full 13):
par new generation total 943744K, used 13891K [0x00000006c3000000, 0x0000000703000000, 0x0000000703000000)
eden space 838912K, 0% used [0x00000006c3000000, 0x00000006c3000000, 0x00000006f6340000)
from space 104832K, 13% used [0x00000006fc9a0000, 0x00000006fd730c68, 0x0000000703000000)
to space 104832K, 0% used [0x00000006f6340000, 0x00000006f6340000, 0x00000006fc9a0000)
concurrent mark-sweep generation total 3096576K, used 1262843K [0x0000000703000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 198589K, capacity 216656K, committed 216804K, reserved 1239040K
class space used 23380K, capacity 26312K, committed 26340K, reserved 1048576K
}
2017-09-07T00:37:58.004+0800: 1600478.268: [CMS-concurrent-sweep: 1.853/1.884 secs] [Times: user=2.96 sys=0.42, real=1.89 secs]
2017-09-07T00:37:58.018+0800: 1600478.281: [CMS-concurrent-reset-start]
2017-09-07T00:37:58.024+0800: 1600478.287: [CMS-concurrent-reset: 0.006/0.006 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
# --- Full GC end ---
# --- Young GC start ---
{Heap before GC invocations=124401 (full 13):
par new generation total 943744K, used 852803K [0x00000006c3000000, 0x0000000703000000, 0x0000000703000000)
eden space 838912K, 100% used [0x00000006c3000000, 0x00000006f6340000, 0x00000006f6340000)
from space 104832K, 13% used [0x00000006fc9a0000, 0x00000006fd730c68, 0x0000000703000000)
to space 104832K, 0% used [0x00000006f6340000, 0x00000006f6340000, 0x00000006fc9a0000)
concurrent mark-sweep generation total 3096576K, used 737871K [0x0000000703000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 198498K, capacity 216446K, committed 216804K, reserved 1239040K
class space used 23360K, capacity 26277K, committed 26340K, reserved 1048576K
2017-09-07T00:38:01.461+0800: 1600481.725: [GC (Allocation Failure) 1600481.725: [ParNew
Desired survivor size 53673984 bytes, new threshold 6 (max 6)
- age 1: 9233632 bytes, 9233632 total
- age 2: 4556000 bytes, 13789632 total
- age 3: 70352 bytes, 13859984 total
- age 4: 69232 bytes, 13929216 total
- age 5: 62736 bytes, 13991952 total
- age 6: 167856 bytes, 14159808 total
: 852803K->16546K(943744K), 0.0195611 secs] 1590674K->754495K(4040320K), 0.0201271 secs] [Times: user=0.05 sys=0.02, real=0.03 secs]
Heap after GC invocations=124402 (full 13):
par new generation total 943744K, used 16546K [0x00000006c3000000, 0x0000000703000000, 0x0000000703000000)
eden space 838912K, 0% used [0x00000006c3000000, 0x00000006c3000000, 0x00000006f6340000)
from space 104832K, 15% used [0x00000006f6340000, 0x00000006f7368808, 0x00000006fc9a0000)
to space 104832K, 0% used [0x00000006fc9a0000, 0x00000006fc9a0000, 0x0000000703000000)
concurrent mark-sweep generation total 3096576K, used 737949K [0x0000000703000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 198498K, capacity 216446K, committed 216804K, reserved 1239040K
class space used 23360K, capacity 26277K, committed 26340K, reserved 1048576K
}
# --- Young GC end ---