Bug in G1GC it performs Full GC when code cache is full resulting in overkill

[Martin Makundi]

Ok, will rebuild it. However, it does work if I explicitly
instantiate, for example a huge string or something.

And I can see it working on the logs:
2013-06-10T17:18:35.179+0300 - 37sec -  at
java.lang.ThreadLocal$ThreadLocalMap.access$100(ThreadLocal.java:261)
        at java.lang.ThreadLocal.set(ThreadLocal.java:183)
        at com.google.monitoring.runtime.instrumentation.AllocationRecorder.recordAllocation(Unknown
Source)
        at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1517)
        at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1493)
        at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1416)

Nevertheless, I rebuilt it and will investigate logs again tomorrow.

**
Martin

2013/6/10 Thomas Schatzl <thomas.schatzl at oracle.com>:
> Hi,
>
> On Mon, 2013-06-10 at 16:32 +0300, Martin Makundi wrote:
>> Hi!
>>
>> >> Does this make sense?
>> >
>> > To me, the log indicates that there are multiple threads trying to
>> > allocate large objects, all of them failing to do so, only then
>> > triggering the gc.
>>
>> Sizes of the allocations seem too close to each other to be multiple threads.
>>
>> Is it possible that the gc is racing against itself in some
>> re-allocation algorithm?
>
> The allocation after the full gc occurs inside the safepoint - so no.
>
> The collector tries this allocation twice before actually doing the
> collection, both of them failing. So you get two sets of messages. I.e.
> first the gc tries outside the safepoint and fails, then schedules a
> safepoint. Within that safepoint the code tries again first in the hope
> that another previous safepoint might have freed enough space.
>
> This explains the messages, as every time you get the "attempt heap
> expansion", "expand the heap" and "did not expand the heap" message.
>
>> > I assume you checked that the log messages are not possibly printed
>> > after the gc? The instrumentation invokes the allocation sampler after
>> > allocation. So in this case, the threads will block at the allocation,
>> > wait for gc, and only after that print the expected messages. There may
>> > also be a delay between the gc output and the allocation information.
>>
>> I did check, not even a single 30mb allocation in today's log.
>>
>> > Maybe looking at the code for the instrumentation helps finding this
>> > issue (this is the first one such bytecode rewriting tool that looked
>> > simple to use that I found as example).
>>
>> You mean change instrumentation or debug it? We use exactly this one:
>> https://code.google.com/p/java-allocation-instrumenter/
>
> Something like that; I really do not know why the messages do not show
> up in the log. The only idea I would have at the moment is that there is
> something wrong with the instrumentation, i.e. for some reason not all
> allocation sites are instrumented.
>
> Maybe rebuilding this instrumenter with current libraries may help.
>
> hth,
> Thomas
>
>