JDK-8224030 : Old Gen usage in MemoryUsage.getCollectionUsage() not updated for young collections
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 8,11.0.2,12,13
  • Priority: P4
  • Status: Resolved
  • Resolution: Duplicate
  • OS: generic
  • CPU: generic
  • Submitted: 2019-05-14
  • Updated: 2019-06-12
  • Resolved: 2019-06-12
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 13
13Resolved
Related Reports
Duplicate :  
Relates :  
Description
ADDITIONAL SYSTEM INFORMATION :
Linux 64 bit, Windows 10 64 bit

A DESCRIPTION OF THE PROBLEM :
Value returned by java.lang.management.MemoryUsage.getUsed() for eden space usage does not match with the value shown by jcmd <pid> GC.heap_info command. Following code always shows eden space usage as 0.


STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
Following code prints the memory usage on console. Once the program prints memory usage, put it in background and capture the jcmd output using "jcmd <pid> GC.heap_info" command. Compare the eden space usage values between these two approaches.

EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
Eden space usage as reported by java.lang.management.MemoryUsage should be close to the value reported by jcmd output.
ACTUAL -
Eden space usage reported by java.lang.management.MemoryUsage is always 0.

---------- BEGIN SOURCE ----------
import java.lang.management.ManagementFactory;
import java.lang.management.MemoryPoolMXBean;
import java.lang.management.MemoryUsage;
import java.util.HashSet;

public class HeapUsageTest {

	public HeapUsageTest()
	{
        System.out.println("Before ");
        printHeapUsage();
        HashSet<String> set = new HashSet<>();
        for (int i = 0; i<10000000; i++) {
            set.add(String.valueOf(i));
        }
        System.out.println("After");
        printHeapUsage();
		
	}
    public static void main(String[] args) throws InterruptedException {
    	new HeapUsageTest();
        Thread.sleep(1000000);
    }

    private void printHeapUsage() {
        for (MemoryPoolMXBean mpbean :
             ManagementFactory.getMemoryPoolMXBeans()) {
            MemoryUsage usage = mpbean.getCollectionUsage();
            if (usage != null) {
                long max = usage.getMax();
                long used = usage.getUsed();            
                System.out.println(mpbean.getName() + " Used " + used + ", Max " + max);
            }
        }
		
    }
}

---------- END SOURCE ----------

FREQUENCY : always



Comments
The JavaDoc on MemoryUsage.getCollectionUsage() states that it "Returns the memory usage after the Java virtual machine most recently expended effort in recycling unused objects in this memory pool" This means that for non-G1 collectors the current result is as expected, as during young GC they do not expend any effort on GC in the old gen/tenured pool (removing the tags). For G1 this , as it always expends (even if little) effort for reclaiming old gen (humongous) objects in every GC (at least if that feature is enabled); this will be fixed automatically with JDK-8196989.
12-06-2019

After some more testing and looking, the issue is that the "Young GC" memory manager does not even contain the "Old" pool, so it does not update that pool. Adding the old pools of the various generational collectors to the "Young GC" memory manager fixes this.
07-06-2019

[~psonal]: this is normal: getCollectionUsage() returns memory usage after GC, where eden is typically empty. Jcmd reports current usage (i.e. getUsage() of the memory pools) which is likely to be different.
16-05-2019

Eden usage after GC is almost always zero for all collectors (always for G1), so that's not a bug. However Old Gen Used seems wrong for all collectors; and actually I can never reproduce a case where Old Gen Used != 0 (unless a Full GC or a concurrent cycle is happening - that may have happened in your example for Parallel GC), even with 8u212. Some digging showed that the problem seems to be the code in GCMemoryManager::gc_end() where it says (jdk/jdk code): void GCMemoryManager::gc_end(bool recordPostGCUsage, bool recordAccumulatedGCTime, bool recordGCEndTime, bool countCollection, GCCause::Cause cause, bool allMemoryPoolsAffected) { [...] if (recordPostGCUsage) { // (1) int i; // keep the last gc statistics for all memory pools for (i = 0; i < MemoryService::num_memory_pools(); i++) { MemoryPool* pool = MemoryService::get_memory_pool(i); MemoryUsage usage = pool->get_memory_usage(); HOTSPOT_MEM_POOL_GC_END( (char *) name(), strlen(name()), (char *) pool->name(), strlen(pool->name()), usage.init_size(), usage.used(), usage.committed(), usage.max_size()); _current_gc_stat->set_after_gc_usage(i, usage); } // Set last collection usage of the memory pools managed by this collector for (i = 0; i < num_memory_pools(); i++) { MemoryPool* pool = get_memory_pool(i); MemoryUsage usage = pool->get_memory_usage(); if (allMemoryPoolsAffected || pool_always_affected_by_gc(i)) { // (2) // Compare with GC usage threshold pool->set_last_collection_usage(usage); // (3) LowMemoryDetector::detect_after_gc_memory(pool); } } } The code at (3) is supposed to update the "Used" member of the MemoryMXBean; while (1) passes because recordPostGCUsage seems to be true for all code, the condition at (2) seems wrong: this is false for all collectors for young gcs for the old pool, i.e. they explicitly pass in allMemoryPoolsAffected == false for those kind of gcs, and pool_always_affected_by_gc(i) is false for the old pool in young gc case. This is wrong, because of course at least some young gcs affect the old memory pool too as they copy objects into it. Non-generational collectors should not be affected by this. I think this is a very old issue if not a day-one issue as e.g. 7u131 and 8u141 show the same problem (maybe this is intentional - would be strange?); they may not have the GC.heap_info jcmd command, but by running with -XX:+AlwaysTenure and making sure that only a young collection occurs, all collectors show "Old Gen Used 0".
16-05-2019

JDK-8195115 fixed a similar issue for G1 mixed collections (but G1 young collections also may affect old gen usage, and all generational collectors seem to be affected).
16-05-2019

Note that in testing you need to make sure that survivor space does not absorb all allocations. In that case "Old Gen Used 0" would be correct too. :)
16-05-2019

Additional Information from submitter: In my test with parallelGC as well as parallelOldGC, eden space usage is reported as 0 using MemoryUsage when jcmd reports non-zero eden space usage.
16-05-2019

It works fine with ParallelGC, looks like issue is with G1 ==With ParallelGC== -sh-4.1$ /scratch/fairoz/JAVA/jdk8/jdk1.8.0_212_GA/bin/java HeapUsageTest Before PS Eden Space Used 0, Max 1239941120 PS Survivor Space Used 0, Max 9437184 PS Old Gen Used 0, Max 2518155264 After PS Eden Space Used 0, Max 807403520 PS Survivor Space Used 175603728, Max 175636480 PS Old Gen Used 477860640, Max 2518155264 ==With G1== -sh-4.1$ /scratch/fairoz/JAVA/jdk8/jdk1.8.0_212_GA/bin/java -XX:+UseG1GC HeapUsageTest Before G1 Eden Space Used 0, Max -1 G1 Survivor Space Used 0, Max -1 G1 Old Gen Used 0, Max 3776970752 After G1 Eden Space Used 0, Max -1 G1 Survivor Space Used 19922944, Max -1 G1 Old Gen Used 0, Max 3776970752 This reminds me JDK-8175375, which i had analyzed for some time.
16-05-2019

Running on JDK 13 ea b20 gives the below output == -sh-4.1$ /scratch/fairoz/JAVA/jdk13/jdk-13-ea+20/bin/java HeapUsageTest Before G1 Eden Space Used 0, Max -1 G1 Old Gen Used 0, Max 3776970752 G1 Survivor Space Used 0, Max -1 After G1 Eden Space Used 0, Max -1 G1 Old Gen Used 0, Max 3776970752 G1 Survivor Space Used 16777216, Max -1 Eden Space used, before and after returns 0.
16-05-2019