Huge difference in GC pause time and total application pause time.

Tue Oct 6 17:52:27 UTC 2015

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
>
>
>
>
>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20151006/76d2ed56/attachment-0001.html>