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