JMV GC logs don't show CMS events

Question

This is a capture of the 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

This is when there is a Full GC:

[Times: user=4.05 sys=0.00, real=4.04 secs]

Is that a stop-of-the-world pause?

I was expecting to see this:

[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

But this happened only once shortly after the start of the JVM, and never again.

I was thinking that the JVM stopped using the CMS GC, so I checked:

>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.

Concurrent Mark-Sweep GC seems to be running properly.

Is it normal that a Full GC happens without CMS GC events in the logs?

If the initial mark and the remark phases don't happen, does it mean that there is no stop-of-the-world pauses?

The machine is a Windows, 24 cores, JDK 8u101.

Here are the flags used:

-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

Do you have code in your application that's explicitly calling `System.gc()`? — Mick Mnemonic, Dec 28 '16 at 19:15
When the CMS fails to clean up garbage fast enough, it falls back to a single threaded GC (the user and real times are the same) — Peter Lawrey, Dec 28 '16 at 19:16

score 2 · Accepted Answer · answered Dec 28 '16 at 19:15

2

The logs tell GC was initiated explicitly by System.gc call:

2016-12-28T08:05:47.072-0800: 53612.476: [Full GC (System.gc())

By default, System.gc invokes stop-the-world collection rather than CMS. If you wish it to invoke CMS, use

-XX:+ExplicitGCInvokesConcurrent

answered Dec 28 '16 at 19:15

apangin

92,924
10
193
247

Or consider disabling explicit GCs altogether with `-XX:+DisableExplicitGC`. It should be up to the GC to decide when it's time to run -- not up to the developer. – Mick Mnemonic Dec 28 '16 at 19:20
1

There are some reasonable uses of System.gc, even by the JVM itself. Disabling it can lead to problems, so it should not be done without testing. – the8472 Dec 28 '16 at 19:30
Could you care to elaborate on these reasonable uses? `System.gc()` is not guaranteed to even do anything, so code relying on these calls seems fundamentally flawed. Good discussion on the topic in [this thread](http://stackoverflow.com/questions/12847151/setting-xxdisableexplicitgc-in-production-what-could-go-wrong). – Mick Mnemonic Dec 28 '16 at 19:44
1

@MickMnemonic For example, JDK relies on Garbage Collection to find finalizable direct ByteBuffers and reclaim native memory they hold (when `MaxDirectMemorySize` limit is reached). Similarly, GC is triggered as the last resort to find and release unreachable MappedByteBuffers when `FileChannel.map` throws `OutOfMemoryError`. – apangin Dec 28 '16 at 20:44
1

See [`Bits.java`](http://hg.openjdk.java.net/jdk8u/jdk8u/jdk/file/e5b1823a897e/src/share/classes/java/nio/Bits.java#l666), [`FileChannelImpl.java`](http://hg.openjdk.java.net/jdk8u/jdk8u/jdk/file/e5b1823a897e/src/share/classes/sun/nio/ch/FileChannelImpl.java#l927) – apangin Dec 28 '16 at 20:46
Do you think that those are _reasonable_ uses? Regarding GC after OoME, isn't that redundant because the [spec says](http://docs.oracle.com/javase/specs/jvms/se7/html/jvms-6.html#jvms-6.3) that GC will be attempted prior to throwing the error. – Mick Mnemonic Dec 28 '16 at 21:25
@MickMnemonic Since there is no other reliable way to find unreachable objects, I think calling `System.gc` after a normal attempt fails is OK. – apangin Dec 29 '16 at 00:50
OutOfMemoryError is thrown there from native code to indicate a failure while allocating a *native* resource, not an object in Heap. – apangin Dec 29 '16 at 00:53
1

I wish that the "System.gc() is not guaranteed to even do anything" meme would stop. Not being guaranteed to do something does not mean it never does anything. Which in turn means for best-effort approaches, such as a last-ditch collection to free bytebuffers it makes sense. It's not great, it's inefficient, but in many circumstances it can be good enough to keep an application running indefinitely where disabling system gc would break it. And that's why I said disabling it needs testing. – the8472 Dec 29 '16 at 15:20
@the8472, and how would you test that your application still runs indefinitely after the change? ;) My point was that you should avoid using `System.gc()` because the application developer has no way to know what that method call actually does (hence "no guarantee"). It could do nothing (if explicit calls are disabled) or in the worst case, it will always run a StW full GC (when using CMS collector with default settings) and the behavior also depends on the JRE. So the "best effort" of a developer can easily cause more problems than just leaving the GC alone. – Mick Mnemonic Dec 30 '16 at 14:18
If you have evidence that disabling `System.gc()` can really "break" an application, I suggest you write an answer to the question I linked to earlier. It would be really valueable information, especially since the majority of the answers seem to suggest that there is essentially no risk. – Mick Mnemonic Dec 30 '16 at 14:21
@MickMnemonic "it will always run a StW full GC" - which may be more or less what's needed since there is no "old gen concurrent GC done" callback. So the only way to be sure that every possible effort has been made to free up native resources is to do a full GC and run finalizers, possibly repeatedly if there are dependency chains. Of course this should not happen in the fast path of any code, they are fallbacks. Which pretty much is what happens in the examples provided by others in this conversation. As for developer control, well, it's not needed, that's why it's best-effort. – the8472 Dec 30 '16 at 17:07
Also, the Q&A you linked already *does* have an answer explaining why explicit GC can have its uses. – the8472 Dec 30 '16 at 17:09

JMV GC logs don't show CMS events

1 Answers1