Review quest for JDK-7067973: test/java/lang/management/MemoryMXBean/CollectionUsageThreshold.java hanging intermittently

Mandy Chung mandy.chung at oracle.com
Tue Dec 3 13:19:38 PST 2013 

Hi Eric,

What I tried to point out is that I'm not seeing the Full GC happened 
when running with

-XX:+UseG1GC -XX:+ExplicitGCInvokesConcurrent

The test hangs if I launch the test with the java launcher on windows 
jdk8-b117.

$ java -XX:+PrintGCDetails -Xmx2m -XX:+UseG1GC -XX:+ExplicitGCInvokesConcurrent CollectionUsageThresho
ld
Collection usage threshold of G1 Old Gen set to 10
Calling System.gc()
[GC pause (System.gc()) (young) (initial-mark), 0.0017152 secs]
    [Parallel Time: 1.4 ms, GC Workers: 4]
       [GC Worker Start (ms): Min: 97.9, Avg: 97.9, Max: 97.9, Diff: 0.0]
       [Ext Root Scanning (ms): Min: 0.1, Avg: 0.7, Max: 1.2, Diff: 1.1, Sum: 2.7]
       [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.4, Max: 0.8, Diff: 0.8, Sum: 1.7]
       [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 1.0]
       [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.3, Avg: 1.3, Max: 1.4, Diff: 0.0, Sum: 5.4]
       [GC Worker End (ms): Min: 99.2, Avg: 99.2, Max: 99.2, 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.2 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: 991.9K(2048.0K)->782.7K(204
8.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.0004602 secs]
[GC concurrent-mark-start]
[GC concurrent-mark-end, 0.0000895 secs]
[GC remark [GC ref-proc, 0.0001248 secs], 0.0008436 secs]
  [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC cleanup 803K->803K(2048K), 0.0001712 secs]
  [Times: user=0.00 sys=0.00, real=0.00 secs]

If I ran the test with jtreg, it passes but if you looked at the log, 
you will find that the Full GC happens when it fails to allocate an 
object (this explains why you need to set -Xmx2m to make the test passes).

[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]

There is some mystery with -XX:+UseG1GC and 
-XX:+ExplicitGCInvokesConcurrent that we will need to consult with the 
GC team.  -Xmx2m would mask the problem.  I suggest to take out line 38 
and 39 and file a bug for further investigation.

If the serviceability team doesn't object this patch, I can sponsor it 
and push it for you.

Mandy

On 11/27/2013 9:21 PM, Eric Wang wrote:
> Hi Mandy,
>
> Yes, I have tested and all settings are passed, as you mentioned the 
> test hangs with -XX:+UseG1GC -XX:+ExplicitGCInvokesConcurrent and 
> default heap size as no GC happens on Old Gen. That is why to add 
> -Xmx2m and big object to make sure GC happens.
>
> I didn't realized the -Xconcgc is same as -XX:+UseConcMarkSweepGC, i 
> have updated the webrev:
> http://cr.openjdk.java.net/~ewang/JDK-7067973/webrev.00/ 
> <http://cr.openjdk.java.net/%7Eewang/JDK-7067973/webrev.00/>
>
> Thanks,
> Eric
> On 2013/11/27 10:17, Mandy Chung wrote:
>> Hi Eric,
>>
>> I'll defer this to the serviceability team to sponsor it and also get 
>> one more review.
>>
>> I don't think you need all 7 @runs.  -Xconcgc is equivalent to 
>> setting -XX:+UseConcMarkSweepGC. For G1 and CMS, you should use 
>> -XX:+ExplicitGCInvokesConcurrent so that System.gc will force a GC in 
>> foreground that you can count the GC reliably. The test wants to get 
>> notified for each System.gc and if there is any GC caused by 
>> allocation failure, the test would fail due to the unexpected GC 
>> count.  It seems that you may run into this issue setting -Xmx2m.
>>
>> Have you got the test passed in all settings?   I'm seeing that the 
>> test hangs with -XX:+UseG1GC -XX:+ExplicitGCInvokesConcurrent without 
>> -Xmx2m.  Looks like there is no GC in the old gen - I'm not familiar 
>> with G1 if it allocates the big object in the old gen.  Jarolsav - 
>> can you help Eric diagnose this issue?  I recalled you ran into 
>> something like that before - maybe Staffan?
>>
>> thanks
>> Mandy
>>
>> On 11/25/2013 8:53 PM, Eric Wang wrote:
>>> Hi Mandy,
>>>
>>> 1. for L34-40, executing tests with 7 settings is trying to cover 
>>> more cases (normal cases and special cases), especially last 3 
>>> settings, as found that the test hung if using vm option 
>>> "-XX:+ExplicitGCInvokesConcurrent" with one of 3 options 
>>> -XX:+UseG1GC, -XX:+UseConcMarkSweepGC or -Xconcgc
>>>
>>> 2. for L61, that is right, the test has been updated. please review.
>>> http://cr.openjdk.java.net/~ewang/JDK-7067973/webrev.00/ 
>>> <http://cr.openjdk.java.net/%7Eewang/JDK-7067973/webrev.00/>
>>>
>>> Thanks,
>>> Eric
>>> On 2013/11/26 8:37, Mandy Chung wrote:
>>>> Hi Eric,
>>>>
>>>> On 11/24/2013 7:41 PM, Eric Wang wrote:
>>>>> Hi Mandy & All,
>>>>>
>>>>> Sorry for late!
>>>>> The webrev below is just finished based on the comments from 
>>>>> peers, please help to review.
>>>>> http://cr.openjdk.java.net/~ewang/JDK-7067973/webrev.00/ 
>>>>> <http://cr.openjdk.java.net/%7Eewang/JDK-7067973/webrev.00/>
>>>>>
>>>>
>>>> Thanks for the patch that looks okay.  Some comments:
>>>>
>>>> L34-40: can you explain why you want to run all 7 settings? I would 
>>>> expect one for each collector.
>>>> L61: I think the static checker variable is meant to be a local 
>>>> variable (and looks like "pools" and "managers" don't need to be 
>>>> static variable).
>>>>
>>>> Mandy
>>>>
>>>>> Thanks,
>>>>> Eric
>>>>> On 2013/11/15 10:55, Mandy Chung wrote:
>>>>>> Hi Eric,
>>>>>>
>>>>>> On 11/14/2013 6:16 PM, Eric Wang wrote:
>>>>>>> Hi Everyone,
>>>>>>>
>>>>>>> I'm working on the bug 
>>>>>>> https://bugs.openjdk.java.net/browse/JDK-7067973.
>>>>>>>
>>>>>>> It is a test bug as 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.
>>>>>>>
>>>>>>> so the suggested fix is similar as the fix 
>>>>>>> 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 with different GC vmoptions.
>>>>>>
>>>>>> What are you looking for specifically?  I have provided the above 
>>>>>> information.  I need to see the webrev to provide further feedback.
>>>>>>
>>>>>> Mandy
>>>>>
>>>>
>>>
>>
>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/serviceability-dev/attachments/20131203/49f2e523/attachment.html

More information about the serviceability-dev mailing list