JMV GC 日志不显示 CMS 事件
JMV GC logs don't show CMS events
这是 GC 的捕获 activity:
2016-12-28T08:05:47.072-0800: 53612.476: [Full GC (System.gc()) Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 2492815068
Max Chunk Size: 2492815068
Number of Blocks: 1
Av. Block Size: 2492815068
Tree Height: 1
Statistics for IndexedFreeLists:
--------------------------------
Total Free Space: 1479780
Max Chunk Size: 254
Number of Blocks: 38007
Av. Block Size: 38
free=2494294848 frag=0.0012
2016-12-28T08:05:47.072-0800: 53612.477: [CMSsize[3] : demand: 43005713, old_rate: 19873.474609, current_rate: 21466.539063, new_rate: 21578.742188, old_desired: 2484304, new_desired: 2697473
size[4] : demand: 27324699, old_rate: 12728.355469, current_rate: 13639.275391, new_rate: 13718.455078, old_desired: 1591121, new_desired: 1714889
size[5] : demand: 9154997, old_rate: 4212.212891, current_rate: 4569.767578, new_rate: 4593.148438, old_desired: 526552, new_desired: 574171
size[6] : demand: 15027193, old_rate: 6913.491699, current_rate: 7500.906738, new_rate: 7539.797363, old_desired: 864228, new_desired: 942520
size[7] : demand: 5912623, old_rate: 2731.289307, current_rate: 2951.318604, new_rate: 2966.481689, old_desired: 341427, new_desired: 370828
(...)
size[255] : demand: 10, old_rate: 0.004862, current_rate: 0.004992, new_rate: 0.005145, old_desired: 0, new_desired: 0
size[256] : demand: 6, old_rate: 0.000378, current_rate: 0.002995, new_rate: 0.002867, old_desired: 0, new_desired: 0
demand: 1, old_rate: 0.000000, current_rate: 0.000499, new_rate: 0.000499, old_desired: 0, new_desired: 0
CMS: Large block 0x00000001c0dac580
: 6242665K->577521K(25729472K), 4.0199341 secs] 7147914K->577521K(27109632K), [Metaspace: 62263K->62263K(1107968K)]After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 3219433296
Max Chunk Size: 3219433296
Number of Blocks: 1
Av. Block Size: 3219433296
Tree Height: 1
Statistics for IndexedFreeLists:
--------------------------------
Total Free Space: 0
Max Chunk Size: 0
Number of Blocks: 0
free=3219433296 frag=0.0000
, 4.0386555 secs] [Times: user=4.05 sys=0.00, real=4.04 secs]
Heap after GC invocations=18106 (full 93):
par new generation total 1380160K, used 0K [0x0000000140000000, 0x000000019d990000, 0x000000019d990000)
eden space 1226816K, 0% used [0x0000000140000000, 0x0000000140000000, 0x000000018ae10000)
from space 153344K, 0% used [0x00000001943d0000, 0x00000001943d0000, 0x000000019d990000)
to space 153344K, 0% used [0x000000018ae10000, 0x000000018ae10000, 0x00000001943d0000)
concurrent mark-sweep generation total 25729472K, used 577521K [0x000000019d990000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 62263K, capacity 63590K, committed 64724K, reserved 1107968K
class space used 6520K, capacity 6790K, committed 6956K, reserved 1048576K
}
{Heap before GC invocations=18106 (full 93):
par new generation total 1380160K, used 1226794K [0x0000000140000000, 0x000000019d990000, 0x000000019d990000)
eden space 1226816K, 99% used [0x0000000140000000, 0x000000018ae0aa90, 0x000000018ae10000)
from space 153344K, 0% used [0x00000001943d0000, 0x00000001943d0000, 0x000000019d990000)
to space 153344K, 0% used [0x000000018ae10000, 0x000000018ae10000, 0x00000001943d0000)
concurrent mark-sweep generation total 25729472K, used 577521K [0x000000019d990000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 62264K, capacity 63590K, committed 64724K, reserved 1107968K
class space used 6520K, capacity 6790K, committed 6956K, reserved 1048576K
2016-12-28T08:05:54.982-0800: 53620.386: [GC (Allocation Failure) Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 3219433296
Max Chunk Size: 3219433296
Number of Blocks: 1
Av. Block Size: 3219433296
Tree Height: 1
Statistics for IndexedFreeLists:
--------------------------------
Total Free Space: 0
Max Chunk Size: 0
Number of Blocks: 0
free=3219433296 frag=0.0000
这是发生 Full GC 的时间：
[Times: user=4.05 sys=0.00, real=4.04 secs]
这是世界末日暂停吗？
我期待看到这个：
[GC (CMS Initial Mark) [1 CMS-initial-mark: 66557K(367232K)] 69245K(980672K), 0.0017554 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
[CMS-concurrent-mark-start]
[CMS-concurrent-mark: 0.055/0.055 secs] [Times: user=0.28 sys=0.02, real=0.05 secs]
[CMS-concurrent-preclean-start]
[CMS-concurrent-preclean: 0.004/0.004 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
[CMS-concurrent-abortable-preclean-start]
[CMS-concurrent-abortable-preclean: 0.612/0.613 secs] [Times: user=2.66 sys=0.34, real=0.62 secs]
[GC (CMS Final Remark) [YG occupancy: 277822 K (613440 K)]2016-12-28T10:50:09.697-0800: 675.178: [Rescan (parallel) , 0.0745979 sec
但这只在 JVM 启动后不久发生过一次，以后再也没有发生过。
我以为是JVM停止使用CMS GC，于是查了一下：
>jmap -heap 4040
Attaching to process ID 4040, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.101-b13
using parallel threads in the new generation.
using thread-local object allocation.
Concurrent Mark-Sweep GC
Heap Configuration:
MinHeapFreeRatio = 20
MaxHeapFreeRatio = 20
MaxHeapSize = 27917287424 (26624.0MB)
NewSize = 1570308096 (1497.5625MB)
MaxNewSize = 1570308096 (1497.5625MB)
OldSize = 26346979328 (25126.4375MB)
NewRatio = 2
SurvivorRatio = 8
MetaspaceSize = 21807104 (20.796875MB)
CompressedClassSpaceSize = 1073741824 (1024.0MB)
MaxMetaspaceSize = 17592186044415 MB
G1HeapRegionSize = 0 (0.0MB)
Heap Usage:
New Generation (Eden + 1 Survivor Space):
capacity = 1413283840 (1347.8125MB)
used = 1023770376 (976.3435134887695MB)
free = 389513464 (371.46898651123047MB)
72.43911994352104% used
Eden Space:
capacity = 1256259584 (1198.0625MB)
used = 929985424 (886.9032135009766MB)
free = 326274160 (311.15928649902344MB)
74.02812570303941% used
From Space:
capacity = 157024256 (149.75MB)
used = 93784952 (89.44029998779297MB)
free = 63239304 (60.30970001220703MB)
59.726410676322516% used
To Space:
capacity = 157024256 (149.75MB)
used = 0 (0.0MB)
free = 157024256 (149.75MB)
0.0% used
concurrent mark-sweep generation:
capacity = 26346979328 (25126.4375MB)
used = 1572138008 (1499.3076400756836MB)
free = 24774841320 (23627.129859924316MB)
5.967052193832427% used
25704 interned Strings occupying 2377736 bytes.
并发 Mark-Sweep GC 似乎 运行 正确。
在日志中没有 CMS GC 事件的情况下发生 Full GC 是否正常？
如果初始标记和重新标记阶段没有发生，是否意味着没有世界停止暂停？
机器是Windows，24核，JDK8u101.
以下是使用的标志：
-server
-Xms26g
-Xmx26g
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+PrintGCTimeStamps
-XX:+PrintGC
-XX:+PrintGCTimeStamps
-XX:+UseCompressedClassPointers
-XX:+UseCompressedOops
-XX:MaxGCPauseMillis=200
-XX:+UseConcMarkSweepGC
-XX:+UseParNewGC
-XX:+PrintHeapAtGC
-XX:PrintFLSStatistics=2
-XX:+PrintPromotionFailure
日志告诉 GC 是由 System.gc 调用明确启动的：
2016-12-28T08:05:47.072-0800: 53612.476: [Full GC (System.gc())
默认情况下，System.gc 调用 stop-the-world 集合而不是 CMS。如果您希望它调用 CMS，请使用
-XX:+ExplicitGCInvokesConcurrent
这是 GC 的捕获 activity:
2016-12-28T08:05:47.072-0800: 53612.476: [Full GC (System.gc()) Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 2492815068
Max Chunk Size: 2492815068
Number of Blocks: 1
Av. Block Size: 2492815068
Tree Height: 1
Statistics for IndexedFreeLists:
--------------------------------
Total Free Space: 1479780
Max Chunk Size: 254
Number of Blocks: 38007
Av. Block Size: 38
free=2494294848 frag=0.0012
2016-12-28T08:05:47.072-0800: 53612.477: [CMSsize[3] : demand: 43005713, old_rate: 19873.474609, current_rate: 21466.539063, new_rate: 21578.742188, old_desired: 2484304, new_desired: 2697473
size[4] : demand: 27324699, old_rate: 12728.355469, current_rate: 13639.275391, new_rate: 13718.455078, old_desired: 1591121, new_desired: 1714889
size[5] : demand: 9154997, old_rate: 4212.212891, current_rate: 4569.767578, new_rate: 4593.148438, old_desired: 526552, new_desired: 574171
size[6] : demand: 15027193, old_rate: 6913.491699, current_rate: 7500.906738, new_rate: 7539.797363, old_desired: 864228, new_desired: 942520
size[7] : demand: 5912623, old_rate: 2731.289307, current_rate: 2951.318604, new_rate: 2966.481689, old_desired: 341427, new_desired: 370828
(...)
size[255] : demand: 10, old_rate: 0.004862, current_rate: 0.004992, new_rate: 0.005145, old_desired: 0, new_desired: 0
size[256] : demand: 6, old_rate: 0.000378, current_rate: 0.002995, new_rate: 0.002867, old_desired: 0, new_desired: 0
demand: 1, old_rate: 0.000000, current_rate: 0.000499, new_rate: 0.000499, old_desired: 0, new_desired: 0
CMS: Large block 0x00000001c0dac580
: 6242665K->577521K(25729472K), 4.0199341 secs] 7147914K->577521K(27109632K), [Metaspace: 62263K->62263K(1107968K)]After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 3219433296
Max Chunk Size: 3219433296
Number of Blocks: 1
Av. Block Size: 3219433296
Tree Height: 1
Statistics for IndexedFreeLists:
--------------------------------
Total Free Space: 0
Max Chunk Size: 0
Number of Blocks: 0
free=3219433296 frag=0.0000
, 4.0386555 secs] [Times: user=4.05 sys=0.00, real=4.04 secs]
Heap after GC invocations=18106 (full 93):
par new generation total 1380160K, used 0K [0x0000000140000000, 0x000000019d990000, 0x000000019d990000)
eden space 1226816K, 0% used [0x0000000140000000, 0x0000000140000000, 0x000000018ae10000)
from space 153344K, 0% used [0x00000001943d0000, 0x00000001943d0000, 0x000000019d990000)
to space 153344K, 0% used [0x000000018ae10000, 0x000000018ae10000, 0x00000001943d0000)
concurrent mark-sweep generation total 25729472K, used 577521K [0x000000019d990000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 62263K, capacity 63590K, committed 64724K, reserved 1107968K
class space used 6520K, capacity 6790K, committed 6956K, reserved 1048576K
}
{Heap before GC invocations=18106 (full 93):
par new generation total 1380160K, used 1226794K [0x0000000140000000, 0x000000019d990000, 0x000000019d990000)
eden space 1226816K, 99% used [0x0000000140000000, 0x000000018ae0aa90, 0x000000018ae10000)
from space 153344K, 0% used [0x00000001943d0000, 0x00000001943d0000, 0x000000019d990000)
to space 153344K, 0% used [0x000000018ae10000, 0x000000018ae10000, 0x00000001943d0000)
concurrent mark-sweep generation total 25729472K, used 577521K [0x000000019d990000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 62264K, capacity 63590K, committed 64724K, reserved 1107968K
class space used 6520K, capacity 6790K, committed 6956K, reserved 1048576K
2016-12-28T08:05:54.982-0800: 53620.386: [GC (Allocation Failure) Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 3219433296
Max Chunk Size: 3219433296
Number of Blocks: 1
Av. Block Size: 3219433296
Tree Height: 1
Statistics for IndexedFreeLists:
--------------------------------
Total Free Space: 0
Max Chunk Size: 0
Number of Blocks: 0
free=3219433296 frag=0.0000
这是发生 Full GC 的时间：
[Times: user=4.05 sys=0.00, real=4.04 secs]
这是世界末日暂停吗？
我期待看到这个：
[GC (CMS Initial Mark) [1 CMS-initial-mark: 66557K(367232K)] 69245K(980672K), 0.0017554 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
[CMS-concurrent-mark-start]
[CMS-concurrent-mark: 0.055/0.055 secs] [Times: user=0.28 sys=0.02, real=0.05 secs]
[CMS-concurrent-preclean-start]
[CMS-concurrent-preclean: 0.004/0.004 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
[CMS-concurrent-abortable-preclean-start]
[CMS-concurrent-abortable-preclean: 0.612/0.613 secs] [Times: user=2.66 sys=0.34, real=0.62 secs]
[GC (CMS Final Remark) [YG occupancy: 277822 K (613440 K)]2016-12-28T10:50:09.697-0800: 675.178: [Rescan (parallel) , 0.0745979 sec
但这只在 JVM 启动后不久发生过一次，以后再也没有发生过。
我以为是JVM停止使用CMS GC，于是查了一下：
>jmap -heap 4040
Attaching to process ID 4040, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.101-b13
using parallel threads in the new generation.
using thread-local object allocation.
Concurrent Mark-Sweep GC
Heap Configuration:
MinHeapFreeRatio = 20
MaxHeapFreeRatio = 20
MaxHeapSize = 27917287424 (26624.0MB)
NewSize = 1570308096 (1497.5625MB)
MaxNewSize = 1570308096 (1497.5625MB)
OldSize = 26346979328 (25126.4375MB)
NewRatio = 2
SurvivorRatio = 8
MetaspaceSize = 21807104 (20.796875MB)
CompressedClassSpaceSize = 1073741824 (1024.0MB)
MaxMetaspaceSize = 17592186044415 MB
G1HeapRegionSize = 0 (0.0MB)
Heap Usage:
New Generation (Eden + 1 Survivor Space):
capacity = 1413283840 (1347.8125MB)
used = 1023770376 (976.3435134887695MB)
free = 389513464 (371.46898651123047MB)
72.43911994352104% used
Eden Space:
capacity = 1256259584 (1198.0625MB)
used = 929985424 (886.9032135009766MB)
free = 326274160 (311.15928649902344MB)
74.02812570303941% used
From Space:
capacity = 157024256 (149.75MB)
used = 93784952 (89.44029998779297MB)
free = 63239304 (60.30970001220703MB)
59.726410676322516% used
To Space:
capacity = 157024256 (149.75MB)
used = 0 (0.0MB)
free = 157024256 (149.75MB)
0.0% used
concurrent mark-sweep generation:
capacity = 26346979328 (25126.4375MB)
used = 1572138008 (1499.3076400756836MB)
free = 24774841320 (23627.129859924316MB)
5.967052193832427% used
25704 interned Strings occupying 2377736 bytes.
并发 Mark-Sweep GC 似乎 运行 正确。
在日志中没有 CMS GC 事件的情况下发生 Full GC 是否正常？
如果初始标记和重新标记阶段没有发生，是否意味着没有世界停止暂停？
机器是Windows，24核，JDK8u101.
以下是使用的标志：
-server
-Xms26g
-Xmx26g
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+PrintGCTimeStamps
-XX:+PrintGC
-XX:+PrintGCTimeStamps
-XX:+UseCompressedClassPointers
-XX:+UseCompressedOops
-XX:MaxGCPauseMillis=200
-XX:+UseConcMarkSweepGC
-XX:+UseParNewGC
-XX:+PrintHeapAtGC
-XX:PrintFLSStatistics=2
-XX:+PrintPromotionFailure
日志告诉 GC 是由 System.gc 调用明确启动的：
2016-12-28T08:05:47.072-0800: 53612.476: [Full GC (System.gc())
默认情况下，System.gc 调用 stop-the-world 集合而不是 CMS。如果您希望它调用 CMS，请使用
-XX:+ExplicitGCInvokesConcurrent