Understanding High Object Copy Times
nezihyigitbasi at gmail.com
Fri Apr 28 19:06:28 UTC 2017
It was in my first email, but just in case here it is:
2017-04-28 12:05 GMT-07:00 Kirk Pepperdine <kirk at kodewerk.com>:
> Hi Nezih,
> Can you share your GC log.
> Kind regards,
> Kirk Pepperdine
> On Apr 28, 2017, at 12:52 AM, nezih yigitbasi <nezihyigitbasi at gmail.com>
> My first question is incorrect actually, so I am giving a better example
> to rephrase my question. At time "2017-04-26T03:12:24.259-0700" there is a
> young GC that took 35.47 s, where object copy took 28983.4 ms. In that
> event I see the following log:
> [Eden: 7168.0M(7168.0M)->0.0B(7168.0M) Survivors: 1024.0M->1024.0M
> Heap: 153.4G(160.0G)->149.4G(160.0G)]
> My interpretation for this is, ~4GB of garbage was collected from heap in
> total and we see that eden usage goes down by ~7GB, this means ~3GB of the
> eden was live objects. Is this interpretation correct? If it is, how come
> copying over 3GB takes ~29s? In your answer you said "most of the object
> copy time is dealing with the Remember Set", can you please give some
> details about what kind of operations on rsets are done during the object
> copy phase, and can we see that from these logs?
> Thanks again,
> 2017-04-27 17:20 GMT-07:00 nezih yigitbasi <nezihyigitbasi at gmail.com>:
>> Thanks for the suggestions. We use the default pause time. And here is
>> our entire set of JVM args: https://gist.github.com/
>> I have some followup questions:
>> - In some case the object copy took 39406.8 ms, even if the remembered
>> set is ~30GB isn't this too slow (that's <1GB/s of data)?
>> - Is there any way to reduce the rset overhead?
>> - My initial thought when I saw the high object copy times was there may
>> be some sort of contention to have such a low throughput during the copy.
>> Although it may not be the case here, I just wonder whether there is a way
>> to see the amount of contention from the gc logs?
>> 2017-04-27 16:58 GMT-07:00 Jenny Zhang <yu.zhang at oracle.com>:
>>> Hi, Hezih,
>>> It seems this workload is very heavy on Remember Set. It has about 31G
>>> native memory for RSet (old gen) and still with coarsening.
>>> What is you pause time goal? The default (200ms) might be too small for
>>> you. Can you increase that so G1 can increase the young gen size? Since
>>> there is not much promotion, I guess most of the object copy time is
>>> dealing with the Remember Set.
>>> There are other things you can try, like increase the
>>> G1RSetReginEntries, but the memory footprint will be bigger.
>>> So if you can, I suggest increase the pause time goal first.
>>> On 4/27/2017 9:22 AM, nezih yigitbasi wrote:
>>>> We see huge object copy times (and relatively high termination times)
>>>> during young GCs in our production system running on Java 1.8.0_112-b15.
>>>> You can find the GC logs here: https://gist.github.com/nezihy
>>>> The young GC times start going high after the timestamp
>>>> I will appreciate if you can give some details about:
>>>> - what goes into the "Object Copy" phase during young GCs and how we
>>>> can reduce it.
>>>> - why we see high Termination times and what we can do about it
-------------- next part --------------
An HTML attachment was scrubbed...
More information about the hotspot-gc-dev