RFR: 8008917 CMS: Concurrent mode failure tracing event

[Erik Helin]

Kevin,

On 03/07/2013 05:52 PM, Kevin Walls wrote:
> Hi Erik -
>
> Yes, now you mention it I can see the route to printing the old warning
> or logging the event twice...
>
> I don't think it's reported as a problem, or maybe it's very rare and
> nobody has spotted it.

It is possible to reproduce the problem with a Java program that simply 
allocates until OOM:

   import java.util.ArrayList;

   public class Reproducer {
       public static ArrayList<byte[]> garbage = new ArrayList<byte[]>();
       public static void main(String[] args) {
           while (true) {
               garbage.add(new byte[1024]);
           }
       }
   }

Compile the above Java program and then run:

java -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails 
-XX:-UseCMSCompactAtFullCollection -Xmx100m Reproducer

Depending on how fast machine you have, the Java program will run for 
about 2 seconds and the GC logs will show (near the start of the output):

[GC (Allocation Failure) [ParNew: 30720K->30720K(30720K), 0.0001940 
secs][CMS[CMS-concurrent-mark: 0.035/0.036 secs] [Times: user=0.03 
sys=0.00, real=0.04 secs]
  (concurrent mode failure) (concurrent mode failure)[YG occupancy: 
30720 K (30720 K)][checkpointRootsFinalWork[Rescan (parallel) , 
0.0314620 secs][refProcessingWork[weak refs processing, 0.0000320 
secs][class unloading, 0.0006770 secs][scrub symbol table, 0.0009850 
secs][scrub string table, 0.0000690 secs], 0.0021430 secs], 0.0339750 
secs]: 50655K->50654K(68288K), 0.0972030 secs] 81375K->81374K(99008K), 
[Metaspace: 2662K->2662K(4486K/110592K)], 0.0980400 secs] [Times: 
user=0.11 sys=0.00, real=0.10 secs]

Please notice the two "(concurrent mode failure)" above which are 
printed for the reason I explained in my previous email.

On 03/07/2013 05:52 PM, Kevin Walls wrote:
> But assuming it's not a "user-requested" collection, to get that false
> "should_compact" in acquire_control_and_collect, we need to call
> decide_foreground_collection_type(), and when it calls
> incremental_collection_will_fail(), that returns false.

This is assuming that the flag UseCMSCompactAtFullCollection is true.

On 03/07/2013 05:52 PM, Kevin Walls wrote:
> Possibly that is why we don't see the event reported twice in
> practice***: if we've got to this point, and state>Idling, we are
> usually here because that inc. collection would fail/is failing...

This is most likely the reason, since UseCMSCompactAtFullCollection is 
true by default and if users aren't changing it, then your reasoning is 
correct.

I suggest that we file a separate bug for CMS printing out "(concurrent 
mode failure)" twice, fix that and then we base your trace code on that.

What do you think?

Thanks,
Erik

> Thanks
> Kevin
>
> *** if anybody really does hit this, or think it's likely, we can look
> again...
>
>
>
> On 06/03/13 18:19, Erik Helin wrote:
>> Hi Kevin,
>>
>> I think that there _might_ be a bug in CMS which was present even
>> before you added the event tracing.
>>
>> If you look in aquire_control_and_collect, you will see that
>> "should_compact" can be set to false by
>> decide_foreground_collection_type. If this is the case, then we will
>> end up in do_mark_sweep_work.
>>
>> The problem is that you have already reported, and CMS has already
>> printed, that a concurrent mode failure has occurred in
>> acquire_control_and_collect. Then, when you enter do_mark_sweep_work,
>> you will once again report, and CMS will again print, that concurrent
>> mode failure has happened.
>>
>> I am not 100% sure that I am right, by I believe that this can happen.
>>
>> What do you think?
>>
>> Thanks,
>> Erik
>>
>> On 03/01/2013 06:34 PM, Kevin Walls wrote:
>>> Hi,
>>>
>>> I'd like some reviews on this CMS Concurrent Mode Failure event:
>>>
>>> http://cr.openjdk.java.net/~kevinw/8008917/hotspot/
>>>
>>> The event doesn't actually carry any new information, but it is a
>>> warning we need to capture.
>>>
>>> This is against hsx24, I'll prepare the same, or reviewed, changes
>>> against very latest hotspot also.
>>>
>>> Thanks
>>> Kevin
>>>
>>
>