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

[Martin Makundi]

Hi!

Same result with re-compiled instrumentation. It works if I explicitly
instantiate a large stringbuffer, for example, but not when the gc log
says:

 18176.048: [G1Ergonomics (Heap Sizing) attempt heap expansion,
reason: humongous allocation request failed, allocation request:
46137360 bytes]
 18176.048: [G1Ergonomics (Heap Sizing) expand the heap, requested
expansion amount: 8388608 bytes, attempted expansion amount: 8388608
bytes]
 18176.048: [G1Ergonomics (Heap Sizing) did not expand the heap,
reason: heap expansion operation failed]
 18176.079: [G1Ergonomics (Heap Sizing) attempt heap expansion,
reason: humongous allocation request failed, allocation request:
46137360 bytes]
 18176.079: [G1Ergonomics (Heap Sizing) expand the heap, requested
expansion amount: 8388608 bytes, attempted expansion amount: 8388608
bytes]
 18176.079: [G1Ergonomics (Heap Sizing) did not expand the heap,
reason: heap expansion operation failed]
 18176.079: [G1Ergonomics (Heap Sizing) attempt heap expansion,
reason: allocation request failed, allocation request: 46137360 bytes]
 18176.079: [G1Ergonomics (Heap Sizing) expand the heap, requested
expansion amount: 46137360 bytes, attempted expansion amount: 50331648
bytes]
 18176.079: [G1Ergonomics (Heap Sizing) did not expand the heap,
reason: heap expansion operation failed]
{Heap before GC invocations=525 (full 191):
 garbage-first heap   total 31457280K, used 24727426K
[0x00007f8344000000, 0x00007f8ac4000000, 0x00007f8ac4000000)
  region size 8192K, 54 young (442368K), 54 survivors (442368K)
 compacting perm gen  total 524288K, used 152746K [0x00007f8ac4000000,
0x00007f8ae4000000, 0x00007f8ae4000000)
   the space 524288K,  29% used [0x00007f8ac4000000,
0x00007f8acd52ab68, 0x00007f8acd52ac00, 0x00007f8ae4000000)
No shared spaces configured.
2013-06-11T12:07:03.152+0300: 18176.079: [Full GC
24147M->14651M(30720M), 59.0086320 secs]
 [Times: user=82.99 sys=0.43, real=59.00 secs]
Heap after GC invocations=526 (full 192):
 garbage-first heap   total 31457280K, used 15003001K
[0x00007f8344000000, 0x00007f8ac4000000, 0x00007f8ac4000000)
  region size 8192K, 0 young (0K), 0 survivors (0K)
 compacting perm gen  total 524288K, used 152746K [0x00007f8ac4000000,
0x00007f8ae4000000, 0x00007f8ae4000000)
   the space 524288K,  29% used [0x00007f8ac4000000,
0x00007f8acd52ab68, 0x00007f8acd52ac00, 0x00007f8ae4000000)
No shared spaces configured.
}


**
Martin

2013/6/10 Martin Makundi <martin.makundi at koodaripalvelut.com>:
> 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
>>
>>