JDK-7067973 : test/java/lang/management/MemoryMXBean/CollectionUsageThreshold.java hanging intermittently
  • Type: Bug
  • Component: core-svc
  • Sub-Component: java.lang.management
  • Affected Version: 7,8
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • OS: generic
  • CPU: generic
  • Submitted: 2011-07-16
  • Updated: 2014-12-02
  • Resolved: 2013-12-04
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 8
8 b120Fixed
Related Reports
Relates :  
JDK-8030628 - Update java/lang/management/MemoryMXBean tests to ignore GC setting by jtreg
Relates :  
JDK-6992968 - test/java/lang/management/MemoryMXBean/CollectionUsageThresholdConcMarkSweepGC.sh should not hang
Relates :  
JDK-8066122 - CollectionUsageThreshold.java times out when run with -XX:+ExplicitGCInvokesConcurrent
Relates :  
JDK-8029631 - CollectionUsageThreshold.java fails with -XX:+UseG1GC -XX:+ExplicitGCInvokesConcurrent
Relates :  
JDK-7173460 - G1: java/lang/management/MemoryMXBean/CollectionUsageThreshold.java failes with G1
Description
TESTFAIL:java/lang/management/MemoryMXBean/CollectionUsageThreshold.java

This test was fixed via 6992968 for a similar issue but it looks like we still have a problem. Here's a hang that was observed on jprt-host-x64-1 with the latest jdk8/tl/jdk (basically jdk8-b00 so close to jdk7-b147).

--------------------------------------------------
TEST: java/lang/management/MemoryMXBean/CollectionUsageThreshold.java
JDK under test: (/tmp/jprt/P2/071909.ab23780/testproduct/solaris_i586_5.10-product)
java version "1.8.0-internal"
Java(TM) SE Runtime Environment (build 1.8.0-internal-201107160719.ab23780.jdk-b00)
Java HotSpot(TM) Client VM (build 21.0-b17, mixed mode, sharing)

ACTION: build -- Passed. Build successful
REASON: User specified action: run build CollectionUsageThreshold MemoryUtil 
TIME:   0.277 seconds
messages:
command: build CollectionUsageThreshold MemoryUtil
reason: User specified action: run build CollectionUsageThreshold MemoryUtil 
elapsed time (seconds): 0.277

ACTION: compile -- Passed. Compilation successful
REASON: .class file out of date or does not exist
TIME:   0.277 seconds
messages:
command: compile /tmp/jprt/P2/071909.ab23780/source/test/java/lang/management/MemoryMXBean/CollectionUsageThreshold.java /tmp/jprt/P2/071909.ab23780/source/test/java/lang/management/MemoryMXBean/MemoryUtil.java
reason: .class file out of date or does not exist
elapsed time (seconds): 0.277

ACTION: build -- Passed. All files up to date
REASON: Named class compiled on demand
TIME:   0.0 seconds
messages:
command: build CollectionUsageThreshold
reason: Named class compiled on demand
elapsed time (seconds): 0.0

ACTION: main -- Failed. Execution failed: `main' threw exception: java.lang.InterruptedException
REASON: User specified action: run main/timeout=300 CollectionUsageThreshold 
TIME:   1200.009 seconds
messages:
command: main CollectionUsageThreshold
reason: User specified action: run main/timeout=300 CollectionUsageThreshold 
Timeout signalled after 1,200 seconds
elapsed time (seconds): 1200.009
STDOUT:
Collection usage threshold of Tenured Gen set to 10
Collection usage threshold of Perm Gen set to 10
Calling System.gc()
Notification for Tenured Gen [type = java.management.memory.collection.threshold.exceeded count = 1]
    usage = init = 11206656(10944K) used = 27223440(26585K) committed = 51482624(50276K) max = 178978816(174784K)
notifying the checker thread to check result
Notification for Perm Gen [type = java.management.memory.collection.threshold.exceeded count = 1]
    usage = init = 12582912(12288K) used = 9409144(9188K) committed = 12582912(12288K) max = 67108864(65536K)
notifying the checker thread to check result
Calling System.gc()
notifying main thread to continue - result checking finished
STDERR:
java.lang.InterruptedException
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2017)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2052)
	at java.util.concurrent.CyclicBarrier.dowait(CyclicBarrier.java:227)
	at java.util.concurrent.CyclicBarrier.await(CyclicBarrier.java:355)
	at CollectionUsageThreshold.main(CollectionUsageThreshold.java:172)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:601)
	at com.sun.javatest.regtest.MainAction$SameVMRunnable.run(MainAction.java:680)
	at java.lang.Thread.run(Thread.java:722)

JavaTest Message: Test threw exception: java.lang.InterruptedException
JavaTest Message: shutting down test


TEST RESULT: Failed. Execution failed: `main' threw exception: java.lang.InterruptedException
--------------------------------------------------
Comments
The big object allocation is used to make sure full gc happened when use +UseG1GC or UseConcMarkSweepGC with ExplicitGCInvokesConcurrent. As the fix now doesn't test the 2 senarios, so the big oject allocation is not needed.
10-12-2013
I confirmed with the GC team that System.gc triggers a stop-the-world collection in all collectors. So -XX:+ExplicitGCInvokesConcurrent will do a concurrent GC and thus it explains the test failure.
05-12-2013
With Eric's proposed change, if I launch the test with the following command, the test hangs on windows jdk8-b117: $ java -XX:+PrintGCDetails -Xmx2m -XX:+UseG1GC -XX:+ExplicitGCInvokesConcurrent CollectionUsageThreshold Collection usage threshold of G1 Old Gen set to 10 Calling System.gc() [GC pause (System.gc()) (young) (initial-mark), 0.0014598 secs] [Parallel Time: 1.1 ms, GC Workers: 4] [GC Worker Start (ms): Min: 108.0, Avg: 108.0, Max: 108.0, Diff: 0.0] [Ext Root Scanning (ms): Min: 0.1, Avg: 0.4, Max: 1.1, Diff: 1.0, Sum: 1.6] [Code Root Marking (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Object Copy (ms): Min: 0.0, Avg: 0.5, Max: 0.8, Diff: 0.8, Sum: 2.1] [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.2, Diff: 0.2, Sum: 0.7] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [GC Worker Total (ms): Min: 1.1, Avg: 1.1, Max: 1.1, Diff: 0.0, Sum: 4.4] [GC Worker End (ms): Min: 109.1, Avg: 109.1, Max: 109.1, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Code Root Migration: 0.0 ms] [Clear CT: 0.0 ms] [Other: 0.3 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.1 ms] [Ref Enq: 0.0 ms] [Free CSet: 0.0 ms] [Eden: 1024.0K(1024.0K)->0.0B(1024.0K) Survivors: 0.0B->1024.0K Heap: 1013.0K(2048.0K)->771.1K(20 48.0K)] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC concurrent-root-region-scan-start] [GC concurrent-root-region-scan-end, 0.0006285 secs] [GC concurrent-mark-start] [GC concurrent-mark-end, 0.0001223 secs] [GC remark [GC ref-proc, 0.0000957 secs], 0.0005657 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] [GC cleanup 791K->791K(2048K), 0.0002172 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] ----------------- We need to understand what System.gc() causes when running -XX:+UseG1GC -XX:+ExplicitGCInvokesConcurrent. The test may pass with jtreg in testing -Xmx2m -XX:+UseG1GC -XX:+ExplicitGCInvokesConcurrent because the Full GC happens due to "Allocation Failure". [Full GC (Allocation Failure) 894K->484K(2048K), 0.0020662 secs] [Full GC (Allocation Failure) 863K->525K(2048K), 0.0029365 secs] [Full GC (Allocation Failure) 842K->525K(2048K), 0.0023650 secs] In fact the test with the patch also failed intermittently: command: main -XX:+PrintGCDetails -Xmx2m -XX:+UseConcMarkSweepGC -XX:+ExplicitGCInvokesConcurrent CollectionUsageThreshold reason: User specified action: run main/othervm/timeout=300 -XX:+PrintGCDetails -Xmx2m -XX:+UseConcMarkSweepGC -XX:+ExplicitGCInvokesConcurrent CollectionUsageThreshold java.lang.RuntimeException: Listeners invoked count = 4 expected to be 3 at CollectionUsageThreshold$Checker.fail(CollectionUsageThreshold.java:252) at CollectionUsageThreshold$Checker.checkResult(CollectionUsageThreshold.java:224) at CollectionUsageThreshold$Checker.run(CollectionUsageThreshold.java:215) STATUS:Passed. STATUS:Failed.`main' threw exception: java.lang.RuntimeException: Listeners invoked count = 4 expected to be 3
03-12-2013
Webrev link: http://cr.openjdk.java.net/~ewang/JDK-7067973/webrev.00/
25-11-2013
Per alan, suggested fix re-sent to: http://mail.openjdk.java.net/pipermail/serviceability-dev/2013-November/013161.html
20-11-2013
Suggested Fix to open alias: http://mail.openjdk.java.net/pipermail/core-libs-dev/2013-November/023213.html
14-11-2013
Root Cause: The test doesn't guarantee memory allocated from the Old Gen, if the used memory is zero and doesn't cross the threshold, no notification is sent, so both the main thread and Checker thread are blocked to wait for the GC notification. Suggested Fix: The fix is similar as the fix of ResetPeakMemoryUsage.java http://hg.openjdk.java.net/jdk8/tl/jdk/rev/a0896634ab46 to create big object to make sure the old gen usage crosses the threshold and run test in different GC.
14-11-2013
The test doesn't guarantee memory allocated from the Old Gen which is a bug. What you observed one of the failure mode is that the used size of the memory usage after GC is zero that explains why the test hangs. Both the main thread and Checker thread are waiting for the GC notification but since the used memory is zero and doesn't cross the threshold, no notification is sent.
13-11-2013
Root Cause: It is more likely a test bug than GC issue as if no GC happend on the Old Gen, then no MEMORY_COLLECTION_THRESHOLD_EXCEEDED event triggered. it causes "signals" is not released, so the whole program is blocked
08-11-2013
when executing above test without vmoption ���-XX:+UseG1GC -XX:+ExplicitGCInvokesConcurrent���, the result as below: PS Old Gen set both UsageThreshold and CollectionUsageThreshold to 10 Pools Usage before GC for: PS Old Gen Initial size = 88080384 (86016K) Used size = 27779072 (27128K) Committd size = 88080384 (86016K) Max size = 1411907584 (1378816K) Calling System.gc() Pools Usage after GC for: PS Old Gen Initial size = 88080384 (86016K) Used size = 40753848 (39798K) Committd size = 88080384 (86016K) Max size = 1411907584 (1378816K) notification type=java.management.memory.threshold.exceeded pool name=PS Old Gen count=1 usage=init = 88080384(86016K) used = 27779072(27128K) committed = 88080384(86016K) max = 1411907584(1378816K) notification type=java.management.memory.collection.threshold.exceeded pool name=PS Old Gen count=1 usage=init = 88080384(86016K) used = 40753848(39798K) committed = 88080384(86016K) max = 1411907584(1378816K) Test Passed for the log, we can find the notification MEMORY_COLLECTION_THRESHOLD_EXCEEDED received as expected. But if executing the test with vmoption ���-XX:+UseG1GC -XX:+ExplicitGCInvokesConcurrent���, the result is: G1 Old Gen set both UsageThreshold and CollectionUsageThreshold to 10 Pools Usage before GC for: G1 Old Gen Initial size = 117440512 (114688K) Used size = 35651584 (34816K) Committd size = 109051904 (106496K) Max size = 2118123520 (2068480K) Calling System.gc() Pools Usage after GC for: G1 Old Gen Initial size = 117440512 (114688K) Used size = 42821808 (41818K) Committd size = 102760448 (100352K) Max size = 2118123520 (2068480K) notification type=java.management.memory.threshold.exceeded pool name=G1 Old Gen count=1 usage=init = 117440512(114688K) used = 12209664(11923K) committed = 122683392(119808K) max = 2118123520(2068480K) Exception in thread "main" java.lang.RuntimeException: collection usage should be exceeded at UsageThresholdTest.main(UsageThresholdTest.java:43) The test failed because MEMORY_COLLECTION_THRESHOLD_EXCEEDED not received, also the isCollectionUsageExceeded() always return false. The result is unexpected because the usage after GC is 41818k , it is lager than the CollectionUsageThreshold value 10 bytes which is set in program.
06-11-2013
It looks that if the option -XX:+ExplicitGCInvokesConcurrent is used with XX:+UseG1GC or other 2 options , the notification MEMORY_COLLECTION_THRESHOLD_EXCEEDED doesn't happen. below is a unit test to prove it. public class UsageThresholdTest { private static ArrayList<BeanWrapper> beanList = new ArrayList<>(); private static ArrayList<int[]> arrList = new ArrayList<>(); public static void main(String[] args) throws InterruptedException { MemoryMXBean mm = ManagementFactory.getMemoryMXBean(); List<MemoryPoolMXBean> pools = ManagementFactory.getMemoryPoolMXBeans(); for (MemoryPoolMXBean bean : pools) { if (bean.isCollectionUsageThresholdSupported() && bean.isUsageThresholdSupported()) { bean.setCollectionUsageThreshold(10); bean.setUsageThreshold(10); System.out.println(bean.getName() + " set both UsageThreshold and CollectionUsageThreshold to 10"); beanList.add(new BeanWrapper(bean)); } } NotificationEmitter emitter = (NotificationEmitter) mm; emitter.addNotificationListener(new SensorListener(), null, null); Thread t = new Thread(new MXBeanMonitor()); t.setDaemon(true); t.start(); createBigData(); invokeGC(pools, mm); Thread.sleep(5000); // sleep to print notifications for (BeanWrapper wrapper : beanList) { if (!wrapper.isUsageExceeded()) { throw new RuntimeException("usage should be exceeded"); } if (!wrapper.isCollectionUsageExceeded()) { throw new RuntimeException("collection usage should be exceeded"); } } System.out.println("Test Passed"); } private static void invokeGC(List<MemoryPoolMXBean> pools, MemoryMXBean mm) { for (BeanWrapper wrapper : beanList) { System.out.println("Pools Usage before GC for: " + wrapper.bean.getName()); printMemoryUsage(wrapper.bean.getUsage()); } System.out.println("Calling System.gc()"); mm.gc(); for (BeanWrapper wrapper : beanList) { System.out.println("Pools Usage after GC for: " + wrapper.bean.getName()); printMemoryUsage(wrapper.bean.getUsage()); } } private static class BeanWrapper { private volatile boolean usageExceeded = false; private volatile boolean collectionUsageExceeded = false; private MemoryPoolMXBean bean; public BeanWrapper(MemoryPoolMXBean bean) { this.bean = bean; } public void updateStatus() { if (bean.isUsageThresholdExceeded()) { usageExceeded = true; } if (bean.isCollectionUsageThresholdExceeded()) { collectionUsageExceeded = true; } } public boolean isUsageExceeded() { return usageExceeded; } public boolean isCollectionUsageExceeded() { return collectionUsageExceeded; } } private static class SensorListener implements NotificationListener { @Override public void handleNotification(Notification notification, Object handback) { MemoryNotificationInfo minfo = MemoryNotificationInfo. from((CompositeData) notification.getUserData()); System.out.println("notification type=" + notification.getType() + " pool name=" + minfo.getPoolName() + " count=" + minfo.getCount() + " usage=" + minfo.getUsage()); } } private static class MXBeanMonitor implements Runnable { @Override public void run() { while (true) { for (BeanWrapper wrapper : beanList) { wrapper.updateStatus(); try { Thread.sleep(20); } catch (InterruptedException ex) {} } } } } private static void createBigData() { int[] arr = null; // create big data to make sure memory of Old Gen is changed after GC. for (int i = 0; i < 10000; i++) { arr = new int[1000]; arrList.add(arr); } } private static void printMemoryUsage(MemoryUsage usage) { String INDENT = " "; System.out.println(INDENT + formatSize("Initial size ", usage.getInit())); System.out.println(INDENT + formatSize("Used size ", usage.getUsed())); System.out.println(INDENT + formatSize("Committd size ", usage.getCommitted())); System.out.println(INDENT + formatSize("Max size ", usage.getMax())); } private static String formatSize(String name, long value) { StringBuffer buf = new StringBuffer(name + " = " + value); if (value > 0) { buf.append(" (" + (value >> 10) + "K)"); } return buf.toString(); } }
06-11-2013
The test hung if using vm option "-XX:+ExplicitGCInvokesConcurrent" with one of the three options -Xincgc, -XX:+UseG1GC or -Xconcgc. below are 3 examples: /net/sqenfs-1/export1/jdk/re/8/promoted/latest/binaries/linux-amd64/bin/java -Xincgc -XX:+ExplicitGCInvokesConcurrent CollectionUsageThreshold /net/sqenfs-1/export1/jdk/re/8/promoted/latest/binaries/linux-amd64/bin/java -XX:+UseG1GC -XX:+ExplicitGCInvokesConcurrent CollectionUsageThreshold /net/sqenfs-1/export1/jdk/re/8/promoted/latest/binaries/linux-amd64/bin/java -Xconcgc -XX:+ExplicitGCInvokesConcurrent CollectionUsageThreshold
06-11-2013
Aurora history: http://aurora.ru.oracle.com/functional/faces/ChessBoard.xhtml?reportName=J2SETestHistory&parameters=[testNameFilterRegExp]java%2Flang%2Fmanagement%2FMemoryMXBean%2FCollectionUsageThreshold.java[release]1.8.0
05-11-2013
Assigning to Eric
04-11-2013