-
Bug
-
Resolution: Unresolved
-
P5
-
None
-
11.0.5-oracle, 14, 15, 16
(synopsis is provisional, please change as you see fit)
AfterJDK-8048556 was fixed, my tier2 test runs caught a failure like this:
$ CONF=linux-x86_64-server-fastdebug make images run-test TEST=hotspot_gc TEST_VM_OPTS="-XX:+UseParallelGC -XX:+UseParallelOldGC -XX:+UseNUMA"
[2.862s][info][gc] GC(0) Pause Young (Allocation Failure) 113M->9M(992M) 225.825ms
[3.227s][info][gc] GC(1) Pause Young (Allocation Failure) 135M->10M(992M) 115.803ms
[3.387s][info][gc] GC(2) Pause Young (Allocation Failure) 106M->10M(992M) 81.497ms
[3.523s][info][gc] GC(3) Pause Young (Allocation Failure) 113M->10M(992M) 65.679ms
[3.675s][info][gc] GC(4) Pause Young (GCLocker Initiated GC) 111M->10M(992M) 80.585ms
[3.871s][info][gc] GC(5) Pause Young (Allocation Failure) 116M->11M(1013M) 94.161ms
[4.114s][info][gc] GC(6) Pause Young (GCLocker Initiated GC) 154M->11M(1005M) 85.957ms
[4.266s][info][gc] GC(7) Pause Young (GCLocker Initiated GC) 96M->11M(1009M) 46.096ms
[4.400s][info][gc] GC(8) Pause Young (GCLocker Initiated GC) 94M->11M(1000M) 49.102ms
...
[301.585s][info][gc] GC(2820) Pause Young (GCLocker Initiated GC) 255M->84M(528M) 5.565ms
[301.670s][info][gc] GC(2821) Pause Young (GCLocker Initiated GC) 303M->85M(528M) 4.062ms
[301.739s][info][gc] GC(2822) Pause Young (GCLocker Initiated GC) 255M->86M(528M) 3.772ms
[301.803s][info][gc] GC(2823) Pause Young (GCLocker Initiated GC) 264M->86M(528M) 4.339ms
[301.865s][info][gc] GC(2824) Pause Young (GCLocker Initiated GC) 269M->87M(528M) 4.608ms
Done.
];
stderr: []
exitValue = 0
java.lang.RuntimeException: '\[gc\s*\] .* \(GCLocker Initiated GC\) [1-9][0-9]?M' found in stdout
at jdk.test.lib.process.OutputAnalyzer.stdoutShouldNotMatch(OutputAnalyzer.java:388)
at gc.stress.gclocker.TestExcessGCLockerCollections.main(TestExcessGCLockerCollections.java:186)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:565)
at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:298)
at java.base/java.lang.Thread.run(Thread.java:830)
JavaTest Message: Test threw exception: java.lang.RuntimeException
JavaTest Message: shutting down test
Seems like GC(7) and GC(8) fit the "bad" regexp. Is this a test bug? The failure seems very intermittent, though, and caught once on a busy CI server. I failed to reproduce it so far in my configs.
After
$ CONF=linux-x86_64-server-fastdebug make images run-test TEST=hotspot_gc TEST_VM_OPTS="-XX:+UseParallelGC -XX:+UseParallelOldGC -XX:+UseNUMA"
[2.862s][info][gc] GC(0) Pause Young (Allocation Failure) 113M->9M(992M) 225.825ms
[3.227s][info][gc] GC(1) Pause Young (Allocation Failure) 135M->10M(992M) 115.803ms
[3.387s][info][gc] GC(2) Pause Young (Allocation Failure) 106M->10M(992M) 81.497ms
[3.523s][info][gc] GC(3) Pause Young (Allocation Failure) 113M->10M(992M) 65.679ms
[3.675s][info][gc] GC(4) Pause Young (GCLocker Initiated GC) 111M->10M(992M) 80.585ms
[3.871s][info][gc] GC(5) Pause Young (Allocation Failure) 116M->11M(1013M) 94.161ms
[4.114s][info][gc] GC(6) Pause Young (GCLocker Initiated GC) 154M->11M(1005M) 85.957ms
[4.266s][info][gc] GC(7) Pause Young (GCLocker Initiated GC) 96M->11M(1009M) 46.096ms
[4.400s][info][gc] GC(8) Pause Young (GCLocker Initiated GC) 94M->11M(1000M) 49.102ms
...
[301.585s][info][gc] GC(2820) Pause Young (GCLocker Initiated GC) 255M->84M(528M) 5.565ms
[301.670s][info][gc] GC(2821) Pause Young (GCLocker Initiated GC) 303M->85M(528M) 4.062ms
[301.739s][info][gc] GC(2822) Pause Young (GCLocker Initiated GC) 255M->86M(528M) 3.772ms
[301.803s][info][gc] GC(2823) Pause Young (GCLocker Initiated GC) 264M->86M(528M) 4.339ms
[301.865s][info][gc] GC(2824) Pause Young (GCLocker Initiated GC) 269M->87M(528M) 4.608ms
Done.
];
stderr: []
exitValue = 0
java.lang.RuntimeException: '\[gc\s*\] .* \(GCLocker Initiated GC\) [1-9][0-9]?M' found in stdout
at jdk.test.lib.process.OutputAnalyzer.stdoutShouldNotMatch(OutputAnalyzer.java:388)
at gc.stress.gclocker.TestExcessGCLockerCollections.main(TestExcessGCLockerCollections.java:186)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:565)
at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:298)
at java.base/java.lang.Thread.run(Thread.java:830)
JavaTest Message: Test threw exception: java.lang.RuntimeException
JavaTest Message: shutting down test
Seems like GC(7) and GC(8) fit the "bad" regexp. Is this a test bug? The failure seems very intermittent, though, and caught once on a busy CI server. I failed to reproduce it so far in my configs.
- is blocked by
-
JDK-8227225 ParallelGC: add subspace transitions for young gen for gc+heap=info log lines
- Resolved
- relates to
-
JDK-8192647 GClocker induced GCs can starve threads requiring memory leading to OOME
- Open
-
JDK-8048556 Unnecessary GCLocker-initiated young GCs
- Resolved