Huge difference in GC pause time and total application pause time.
Yu Zhang
yu.zhang at oracle.com
Tue Oct 6 18:19:10 UTC 2015
Naman,
Are you on Linux? Do you have Transparent Huge Page on from the system
level?
Thanks,
Jenny
On 10/6/2015 10:52 AM, Yu Zhang wrote:
> Naman,
>
> It seems to me not related to safe point. Because the entry has
> [Times: user=0.38 sys=0.02, real=0.75 secs]
> indicating it is 0.75 sec when collection at safe point is done.
> What I do not understand is the time 0.0355102 sec is printed after
> the evacuation is done. The only difference between 0.0355102 and last
> entry is some book keeping stuff. But we are using much more user and
> real time. The big difference between real and user time means the gc
> threads can not be scheduled to get cpu. But no explanation for
> 0.0355102 vs 0.38 sec.
>
> Do you see this happen a lot? Is your system cpu saturated?
>
> Thanks,
> Jenny
> On 10/6/2015 9:32 AM, Naman Jain wrote:
>> Hey jenny,
>>
>> JVM version used is:
>> java version "1.8.0_40"
>> Java(TM) SE Runtime Environment (build 1.8.0_40-b26)
>> Java HotSpot(TM) 64-Bit Server VM (build 25.40-b25, mixed mode)
>>
>> -Naman
>>
>>
>>
>> On Tuesday, 6 October 2015 9:56 PM, Naman Jain
>> <naman.jain1894 at yahoo.in> wrote:
>>
>>
>> Hey Jenny,
>>
>> I checked the sar files, there was no swapping or waiting on i/o.
>> The jvm I am using is:
>> Java HotSpot(TM) 64-Bit Server VM (25.40-b25) for linux-amd64 JRE
>> (1.8.0_40-b26)
>> Can you tell me any other reason which might have caused this ?
>> Also, does safepoint have anything do with this ?
>> Thanks
>>
>> Naman
>>
>>
>>
>> On Tuesday, 6 October 2015 9:00 PM, Yu Zhang <yu.zhang at oracle.com> wrote:
>>
>>
>> Naman,
>>
>> This entry is very strange,
>> it has 0.0355102 sec for gc pause, but the time stamp at the bottom has
>> [Times: user=0.38 sys=0.02, real=0.75 secs]
>> The real time matches PrintGCApplicationStoppedTime.
>> Since there are 18 gc threads, if not blocked by something, the real
>> time should be smaller than user time.
>> can you check if the system is swapping or waiting on i/o?
>> Which JVM are you using?
>>
>> Thanks,
>> Jenny
>> On 10/6/2015 1:58 AM, Naman Jain wrote:
>>> Hey Everyone,
>>>
>>> G1 GC log:
>>> 2015-10-05T14:54:35.518+0000: 549629.568: [GC pause (G1 Evacuation
>>> Pause) (young)
>>> Desired survivor size 322961408 bytes, new threshold 15 (max 15)
>>> - age 1: 5292232 bytes, 5292232 total
>>> - age 2: 1201264 bytes, 6493496 total
>>> - age 3: 377376 bytes, 6870872 total
>>> - age 4: 440752 bytes, 7311624 total
>>> - age 5: 201976 bytes, 7513600 total
>>> - age 6: 77616 bytes, 7591216 total
>>> - age 7: 28824 bytes, 7620040 total
>>> - age 8: 55312 bytes, 7675352 total
>>> - age 9: 55432 bytes, 7730784 total
>>> - age 10: 14272 bytes, 7745056 total
>>> - age 11: 16872 bytes, 7761928 total
>>> - age 12: 18208 bytes, 7780136 total
>>> - age 13: 11656 bytes, 7791792 total
>>> - age 14: 15800 bytes, 7807592 total
>>> - age 15: 33960 bytes, 7841552 total
>>> 549629.569: [G1Ergonomics (CSet Construction) start choosing CSet,
>>> _pending_cards: 14904, predicted base time: 20.98 ms, remaining
>>> time: 19.02 ms, target pause time: 40.00 ms]
>>> 549629.569: [G1Ergonomics (CSet Construction) add young regions to
>>> CSet, eden: 1224 regions, survivors: 4 regions, predicted young
>>> region time: 10.73 ms]
>>> 549629.569: [G1Ergonomics (CSet Construction) finish choosing CSet,
>>> eden: 1224 regions, survivors: 4 regions, old: 0 regions, predicted
>>> pause time: 31.70 ms, target pause time: 40.00 ms]
>>> , *0.0355102 secs*]
>>> [Parallel Time: 21.7 ms, GC Workers: 18]
>>> [GC Worker Start (ms): Min: 549629569.6, Avg: 549629569.8, Max:
>>> 549629569.9, Diff: 0.3]
>>> [Ext Root Scanning (ms): Min: 3.6, Avg: 4.3, Max: 12.7, Diff:
>>> 9.0, Sum: 78.1]
>>> [Update RS (ms): Min: 0.0, Avg: 4.1, Max: 4.7, Diff: 4.7, Sum: 74.6]
>>> [Processed Buffers: Min: 0, Avg: 60.3, Max: 79, Diff: 79, Sum:
>>> 1086]
>>> [Scan RS (ms): Min: 0.1, Avg: 2.2, Max: 2.7, Diff: 2.5, Sum: 40.4]
>>> [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff:
>>> 0.0, Sum: 0.1]
>>> [Object Copy (ms): Min: 8.0, Avg: 10.2, Max: 10.5, Diff: 2.5,
>>> Sum: 183.2]
>>> [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum:
>>> 2.5]
>>> [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2,
>>> Sum: 2.0]
>>> [GC Worker Total (ms): Min: 20.9, Avg: 21.2, Max: 21.4, Diff:
>>> 0.5, Sum: 381.0]
>>> [GC Worker End (ms): Min: 549629590.9, Avg: 549629590.9, Max:
>>> 549629591.1, Diff: 0.2]
>>> [Code Root Fixup: 0.3 ms]
>>> [Code Root Purge: 0.0 ms]
>>> [Clear CT: 0.8 ms]
>>> [Other: 12.6 ms]
>>> [Choose CSet: 0.0 ms]
>>> [Ref Proc: 6.2 ms]
>>> [Ref Enq: 0.5 ms]
>>> [Redirty Cards: 0.4 ms]
>>> [Humongous Reclaim: 0.0 ms]
>>> [Free CSet: 2.9 ms]
>>> [Eden: 4896.0M(4896.0M)->0.0B(4892.0M) Survivors: 16.0M->20.0M Heap:
>>> 6505.9M(8192.0M)->1611.1M(8192.0M)]
>>> [Times: user=0.38 sys=0.02, real=0.75 secs]
>>> 2015-10-05T14:54:36.272+0000: 549630.322: Total time for which
>>> application threads were stopped:*0.7695049* seconds, Stopping
>>> threads took: 0.0004596 seconds
>>>
>>> As you can see that young GC took around 35ms but the total time for
>>> which application threads were stopped is 769ms. Can anyone tell me
>>> what other pauses are included in this total time ?
>>> Also why pauses other then GC pauses were included in GC logs ?
>>> Earlier I was using CMS. But in CMS I never saw such differences in
>>> GC time and Application thread pause time. Can anyone tell me what
>>> is the reason behind such behaviour ?
>>>
>>> Thanks
>>>
>>> -Naman
>>>
>>>
>>>
>>> _______________________________________________
>>> hotspot-gc-use mailing list
>>> hotspot-gc-use at openjdk.java.net <mailto:hotspot-gc-use at openjdk.java.net>
>>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>>
>>
>>
>>
>>
>
>
>
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20151006/4a5c5bed/attachment-0001.html>
More information about the hotspot-gc-use
mailing list