G1: no concurrent cycle initiation for humongous allocation

[Monica Beckwith]

Hi again, Simone -

Thanks for sending the log file. Two things stand out from the log file-

1) It seems to me that the application has a lot of "humongous" 
allocations <3MB. Please set your -XX:G1HeapRegionSize=8M and you 
shouldn't see (as much of) the behavior where the concurrent marking's 
being pushed off due to mixed GC cycles.
2) High external root scanning times (coupled with incorrect prediction 
times (earlier on in the log)) are the reason why G1 doesn't increase 
it's nursery.

Here's a link to the JavaOne 2013 presentation that has more details on 
humongous objects: http://www.slideshare.net/MonicaBeckwith/con5497.

-Monica


On 10/14/13 3:18 PM, Simone Bordet wrote:
> Hi,
>
> On Mon, Oct 14, 2013 at 12:07 PM, Thomas Schatzl
> <thomas.schatzl at oracle.com> wrote:
>> If a humongous/large object allocation makes the occupied heap (after
>> allocation of the humongous object) larger than the threshold, G1 tries
>> to schedule a concurrent cycle.
>>
>> At the same time G1 still in the mixed-gc phase (cleaning up the regular
>> heap), and the collection policy does not allow initiation of a
>> concurrent cycle during that phase.
>>
>> The message in essence just indicates that.
>>
>> Is there any problem, apart from the messages?
> See the logs excerpt below.
>
> What I think it happens is that the end of the concurrent cycle cleans
> up (as in the "GC Cleanup" phase) a large number of regions because
> they are all garbage (early promotions from young since young is
> small).
> The GC Cleanup phase moves from 509->268 MiB.
>
> Then some time passes (~50s: from 989 to 1041); during this time young
> has not been filled (even if it's only 140 MiB), yet at 1041.161 G1
> reports that 643 MiB are now occupied.
>
> After 1041.161, other 136 lines of the same type happen (and nothing
> else), all of them within 32s, all of them requesting the same
> allocation size.
> The last of these lines happens at 1073.224, showing that during those
> 32s (1073-1041) ~288 MiB have been allocated (931-643 MiB), probably
> all of them as humongous object directly in old generation (because no
> young GC has been triggered despite its small size).
> If the same happened during the prior ~50s between the GC Cleanup and
> 1041.161, then young would still be "empty" but it would explain why a
> concurrent cycle would have been requested: the heap is actually
> indeed over IHOP because of humongous allocations.
>
> At the beginning I could not believe that only humongous allocations
> were happening, but it seems to be the case.
>
> I guess this case is not handled well with the default region size,
> but it's a good case where setting the region size to 3 MiB (because
> the humongous allocations seems all to be of size 1438336=1.4 MiB)
> would "solve" this problem.
>
> If I am wrong in my interpretation, I'd be happy to hear.
>
> Thanks !
>