committed > max in MemoryMXBean#getHeapMemoryUsage()

[Erik Helin]

Hi Daniel,

thanks for letting us know. Since you have only set -Xms512 and -Xmx512 
and you are running on JDK 10 that means you are using the G1 garbage 
collector, so all the calls to pool->get_memory_usage() in the loop will 
end up in g1MemoryPool.cpp [0] which in turn will return cached values 
from the recalculate_sizes code in G1MonitoringSupport [1]. Since you 
are running with -Xmx512m you should have gotten 1 MB sized regions (see 
heapRegion.cpp for details [2]), so the 5 MB _could_ mean that five 
regions were accounted wrongly.

Do you any kind of GC logging from the test run where you encountered 
the bug?

The code in G1MonitoringSupport::recalculate_sizes seems messy enough 
that there could be in a small bug in there. I'm adding hotspot-gc-dev 
since all GC developers might not read serviceability-dev.

Thanks,
Erik

[0]: 
http://hg.openjdk.java.net/jdk/jdk/file/tip/src/hotspot/share/gc/g1/g1MemoryPool.cpp
[1]: 
http://hg.openjdk.java.net/jdk/jdk/file/tip/src/hotspot/share/gc/g1/g1MonitoringSupport.cpp#l182
[2]: 
http://hg.openjdk.java.net/jdk/jdk/file/tip/src/hotspot/share/gc/g1/heapRegion.cpp#l63

On 07/12/2018 03:35 PM, Daniel Mitterdorfer wrote:
> Hi,
> 
> while working on a change in Elasticsearch, I discovered an interesting
> situation related to the implementation of jmm_getMemoryUsage (see
> [jdk-mem-usage]). In one of the test runs, a test failed with the following
> exception:
> 
> java.lang.IllegalArgumentException: committed = 542113792 should be <
> max = 536870912
> at java.lang.management.MemoryUsage.<init>(MemoryUsage.java:166)
> at sun.management.MemoryImpl.getMemoryUsage0(Native Method)
> at sun.management.MemoryImpl.getHeapMemoryUsage(MemoryImpl.java:71)
> at org.elasticsearch.indices.breaker.HierarchyCircuitBreakerService.currentMemoryUsage(HierarchyCircuitBreakerService.java:246)
> [...]
> 
> This happened on MacOS 10.12.6 with JDK 10 (build 10.0.1+10). The only JVM flags
> specified where -Xms512M -Xmx512M. So far this failure occurred only once and I
> could not reproduce it yet.
> 
> The values reported in the exception message are:
> 
> * "max": 536870912 = 512MB (exactly)
> * "committed": 542113792 = 517MB (exactly), i.e. 5MB more than "max".
> 
> As the value of "max" is exactly what we have specified with -Xmx this indicates
> to me that the problem seems to be the calculation of "committed".
> 
> As the value of "max" is exactly what we have specified with -Xmx it seems to
> indicate that the problem is the calculation of "committed". I do not
> understand under which conditions this can happen thus I post this to the
> mailing list in case anybody has ideas what might cause this.
> 
> I plan to run further tests with JVM trace logging enabled
> (-Xlog:gc*=trace,heap*=trace,tlab*=off:stdout:time,pid,tid,level,tags to be
> precise) in the hope that this problem will occur again and I can provide logs
> that help to debug / fix the problem.
> 
> Searching for that error message, there is [JDK-8020530] but that one is about
> *non-heap* memory usage and has already been resolved a while ago. Several
> sources (e.g. [apache-ignite-workaround] or [netbeans-bug]) seem to indicate
> that this problem happened indeed in the wild but what I find odd is that I
> could not find a single ticket in the OpenJDK bug tracker or a discussion on a
> JDK mailing list about this problem.
> 
> I'd be glad to get any pointers on what might cause this or requests for
> additional info that I need to provide to help analyze this problem.
> 
> Thanks,
> Daniel
> 
> [jdk-mem-usage]
> http://hg.openjdk.java.net/jdk-updates/jdk10u/file/142f0ed9ff5b/src/hotspot/share/services/management.cpp#l728
> [JDK-8020530] https://bugs.openjdk.java.net/browse/JDK-8020530
> [apache-ignite-workaround]
> https://github.com/apache/ignite/blob/df4fd65a32/modules/core/src/main/java/org/apache/ignite/internal/managers/discovery/GridDiscoveryManager.java#L336-L346
> [netbeans-bug] https://netbeans.org/bugzilla/show_bug.cgi?id=194733
>