Minor question about logging
Eugeniu Rabii
eugen.rabii at gmail.com
Mon Mar 9 15:11:23 UTC 2020
Yes Stefan, I have already seen that under back-to-back young GCs, those
values are up to date, always.
Thank you for confirming this.
Eugene.
On 3/9/20 10:30 AM, Stefan Johansson wrote:
> Hi,
>
> On 2020-03-09 15:08, Eugeniu Rabii wrote:
>> Hello Stefan,
>>
>> I actually should have been more clear myself on the specific
>> question I have, I am sorry for that.
> No problem.
>
>>
>> Comments inline.
>>
>> On 3/9/20 6:41 AM, Stefan Johansson wrote:
>>> Hi Eugeniu,
>>>
>>> I should have been more clear around that your understanding of the
>>> numbers are correct. But as Thomas also responded, these are
>>> estimates and we might have to start a GC due to other circumstances.
>>>
>>> See more below.
>>>
>>> On 2020-03-09 11:32, Eugeniu Rabii wrote:
>>>> Hello Stefan,
>>>>
>>>> I know these are humongous allocations, the 2 MB was chosen on
>>>> purpose (I could have chose 1 MB too, I know).
>>>>
>>>> The first GC (0 - young collection) is actually the result of the
>>>> allocation of those humongous Objects.
>>>>
>>>> Because the humongous allocation happened, a concurrent GC was
>>>> triggered (GC (1)) that triggers the young collection first (GC
>>>> (0)); these are concepts I do seem do get.
>>>>
>>>> My question here is different. After the young collection is done,
>>>> there are entries like this in logs:
>>>>
>>>> [0.071s][info ][gc,heap ] GC(0) Eden regions: 1->0(9)
>>>> [0.071s][info ][gc,heap ] GC(0) Survivor regions: 0->1(2)
>>>>
>>>> The way I read it it is: there were 1 Eden Regions before the
>>>> collection; everything was cleared from them (that zero) and the
>>>> heuristics just said that the next cycle should have 9 Eden Regions.
>>> Correct, but this is an estimate and we might have to GC before we
>>> fill up the 9 young regions. For example if there are a lot of
>>> humongous allocations. The humongous allocations are as I mentioned
>>> treated differently and aren't considered young.
>>>
>>
>> I understand these are estimates; I also understand these could be
>> ignored. In fact, they are, since GC (2) is _again_ a humongous
>> allocation.
>>
>>
>>>>
>>>> Same explanation would happen for Survivor Regions. As such there
>>>> would be : 11 young, 2 survivor.
>>>>
>>>>
>>>> I am expecting the third cycle (GC (2)) to start with :
>>>>
>>>>
>>>> [0.076s][debug][gc,heap ] GC(2) Heap before GC
>>>> invocations=2 (full 0): .....
>>>>
>>>> [0.076s][debug][gc,heap ] GC(2) region size 1024K, 11
>>>> young (2048K), 2 survivors (1024K)
>>>>
>>>>
>>>> Instead it prints:
>>>>
>>>>
>>>> [0.076s][debug][gc,heap ] GC(2) region size 1024K, 2
>>>> young (2048K), 1 survivors (1024K)
>>>>
>>>>
>>>> Does this makes it a better explanation now?
>>> Your expectation is correct, and if GC(2) isn't caused by a
>>> humongous allocation this is unexpected behavior. It would help a
>>> lot if you could post more of your log, especially the cause for GC(2).
>>
>> Logs attached, but you are correct GC (2) is still a humongous
>> allocation:
>>
>> [0.090s][debug][gc,ergo ] Request concurrent cycle
>> initiation (requested by GC cause). GC cause: G1 Humongous Allocation
>>
>>
>> And now my question: what I REALLY wish for (not sure if possible) is
>> a log statement in GC(1) of how young regions were adjusted because
>> of the humongous allocation - this is the part I was missing.
>>
>> I sort of already realized before posting that those are only
>> estimates, I hoped for some kind of a hint in logs.
> GC(1) is the concurrent cycle initiated by GC(0), and the concurrent
> cycle itself doesn't affect the number of young regions used in the
> next young collection. So to get this number the only thing you can
> really do is comparing the estimate from GC(0) with the actual number
> in GC(2). Or to be more general compare the estimate from the previous
> young collection with the actual number used in the current one. For
> normal young collections the numbers should be equal but there are
> some causes when they are not and one of them is:
> G1 Humongous Allocation
>
> Not sure if this helps, but this is the information you currently have
> in the logs.
>
> Cheers,
> Stefan
>
>>
>>
>>>
>>> Thanks,
>>> Stefan
>>>
>>>>
>>>> Thank you,
>>>>
>>>> Eugene.
>>>>
>>>>
>>>> On 3/9/20 4:14 AM, Stefan Johansson wrote:
>>>>> Hi Eugeniu,
>>>>>
>>>>> The second GC is most likely also caused by having many humongous
>>>>> allocations. This was the cause GC(0) as well, and since your
>>>>> application only allocates large (humongous) objects it will not
>>>>> use a lot of space for other objects.
>>>>>
>>>>> If you are not familiar with the concept of humongous objects in
>>>>> G1, these are objects that are to large to be allocated in the
>>>>> normal fast path. They are instead allocated in separate regions.
>>>>> This requires some special handling and that's the reason we
>>>>> trigger GCs more quickly if a lot of such objects are allocated.
>>>>> In your setup the region size will be 1MB so all objects larger
>>>>> than 500KB will be considered humongous.
>>>>>
>>>>> Hope this helps,
>>>>> StefanJ
>>>>>
>>>>>
>>>>> On 2020-03-08 06:01, Eugeniu Rabii wrote:
>>>>>> Hello,
>>>>>>
>>>>>> I have a very simple program that constantly allocates some byte
>>>>>> arrays (of 2 MB) each (running with the latest jdk-13). I run it
>>>>>> with :
>>>>>>
>>>>>> -Xms20M
>>>>>> -Xmx20M
>>>>>> -Xmn10M
>>>>>> "-Xlog:heap*=debug" "-Xlog:gc*=debug" "-Xlog:ergo*=debug"
>>>>>>
>>>>>>
>>>>>> For example:
>>>>>>
>>>>>> public static void main(String[] args) {
>>>>>> while (true) {
>>>>>> System.out.println(invokeMe());
>>>>>> }
>>>>>> }
>>>>>>
>>>>>> public static int invokeMe() {
>>>>>> int x = 1024;
>>>>>> int factor = 2;
>>>>>> byte[] allocation1 = new byte[factor * x * x];
>>>>>> allocation1[2] = 3;
>>>>>> byte[] allocation2 = new byte[factor * x * x];
>>>>>> byte[] allocation3 = new byte[factor * x * x];
>>>>>> byte[] allocation4 = new byte[factor * x * x];
>>>>>>
>>>>>> return Arrays.hashCode(allocation1) ^
>>>>>> Arrays.hashCode(allocation2)
>>>>>> ^ Arrays.hashCode(allocation3) ^
>>>>>> Arrays.hashCode(allocation4);
>>>>>> }
>>>>>>
>>>>>> In logs, I see something that is puzzling me:
>>>>>>
>>>>>>
>>>>>> [0.066s][debug][gc,ergo ] Request concurrent cycle
>>>>>> initiation (requested by GC cause). GC cause: G1 Humongous
>>>>>> Allocation
>>>>>> [0.066s][debug][gc,heap ] GC(0) Heap before GC
>>>>>> invocations=0 (full 0): garbage-first heap total 20480K, used
>>>>>> 6908K [0x00000007fec00000, 0x0000000800000000)
>>>>>> [0.066s][debug][gc,heap ] GC(0) region size 1024K, 1
>>>>>> young (1024K), 0 survivors (0K)
>>>>>>
>>>>>> OK, so Heap Before: 1 young, 0 survivors.
>>>>>>
>>>>>> Then:
>>>>>>
>>>>>> [0.071s][info ][gc,heap ] GC(0) Eden regions: 1->0(9)
>>>>>> [0.071s][info ][gc,heap ] GC(0) Survivor regions: 0->1(2)
>>>>>> [0.071s][info ][gc,heap ] GC(0) Old regions: 0->0
>>>>>>
>>>>>> So the next cycle will have 9 Eden Regions and 2 Survivor ones
>>>>>> (at least this is how I read the source code of where this is
>>>>>> logged)
>>>>>>
>>>>>> Then a GC(1) concurrent cycle happens:
>>>>>>
>>>>>> [0.071s][info ][gc ] GC(1) Concurrent Cycle
>>>>>>
>>>>>> And the next cycle is where I fail to understand the logging:
>>>>>>
>>>>>> [0.076s][debug][gc,heap ] GC(2) Heap before GC
>>>>>> invocations=2 (full 0): garbage-first heap total 20480K, used
>>>>>> 7148K [0x00000007fec00000, 0x0000000800000000)
>>>>>> [0.076s][debug][gc,heap ] GC(2) region size 1024K, 2
>>>>>> young (2048K), 1 survivors (1024K)
>>>>>>
>>>>>> How come 2 young, 1 survivors? When the previous cycle said 9
>>>>>> Eden, 2 Survivor.
>>>>>>
>>>>>> Thank you,
>>>>>> Eugene.
>>>>>>
>>>>>> _______________________________________________
>>>>>> hotspot-gc-use mailing list
>>>>>> hotspot-gc-use at openjdk.java.net
>>>>>> https://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>>>>>>
More information about the hotspot-gc-use
mailing list