<html><body><div style="color:#000; background-color:#fff; font-family:HelveticaNeue, Helvetica Neue, Helvetica, Arial, Lucida Grande, Sans-Serif;font-size:13px"><div id="yui_3_16_0_1_1444145774385_8796"><span id="yui_3_16_0_1_1444145774385_8874"><font size="2" id="yui_3_16_0_1_1444145774385_8957">Hey Jenny,</font></span></div><div id="yui_3_16_0_1_1444145774385_8797"><span><font size="2"><br></font></span></div><div id="yui_3_16_0_1_1444145774385_8241"><span id="yui_3_16_0_1_1444145774385_8798"><font size="2" id="yui_3_16_0_1_1444145774385_8961">I checked the sar files, there was no swapping or waiting on i/o.</font></span></div><div id="yui_3_16_0_1_1444145774385_8240"><span id="yui_3_16_0_1_1444145774385_8869"><font size="2">The jvm I am using is:</font></span></div><div>
</div><div class="" dir="ltr" id="yui_3_16_0_1_1444145774385_8209"><span class="" id="yui_3_16_0_1_1444145774385_8211"><font size="2" id="yui_3_16_0_1_1444145774385_8962">Java HotSpot(TM) 64-Bit Server VM (25.40-b25) for linux-amd64 JRE (1.8.0_40-b26)</font></span></div><div class="" dir="ltr" id="yui_3_16_0_1_1444145774385_8209"><span class="" id="yui_3_16_0_1_1444145774385_8867"><font size="2" id="yui_3_16_0_1_1444145774385_8963">Can you tell me any other reason which might have caused this ?</font></span></div><div class="" dir="ltr" id="yui_3_16_0_1_1444145774385_8209">Also, does safepoint have anything do with this ?</div><div class="" dir="ltr" id="yui_3_16_0_1_1444145774385_8209"><span class="" id="yui_3_16_0_1_1444145774385_8872"><font size="2" id="yui_3_16_0_1_1444145774385_9002">Thanks </font></span></div><div class="" dir="ltr" id="yui_3_16_0_1_1444145774385_8209"><span class=""><font size="2"><br></font></span></div><div class="" dir="ltr" id="yui_3_16_0_1_1444145774385_8209"><span class="" id="yui_3_16_0_1_1444145774385_8877"><font size="2" id="yui_3_16_0_1_1444145774385_8959">Naman</font></span></div> <br><div class="qtdSeparateBR"><br><br></div><div class="yahoo_quoted" style="display: block;"> <div style="font-family: HelveticaNeue, Helvetica Neue, Helvetica, Arial, Lucida Grande, Sans-Serif; font-size: 13px;"> <div style="font-family: HelveticaNeue, Helvetica Neue, Helvetica, Arial, Lucida Grande, Sans-Serif; font-size: 16px;"> <div dir="ltr"> <font size="2" face="Arial"> On Tuesday, 6 October 2015 9:00 PM, Yu Zhang <yu.zhang@oracle.com> wrote:<br> </font> </div> <br><br> <div class="y_msg_container"><div id="yiv1302500087"><div>
<font size="-1"><tt>Naman,<br clear="none">
<br clear="none">
This entry is very strange, <br clear="none">
it has 0.0355102 sec for gc pause, but the time stamp at the
bottom has<br clear="none">
</tt></font><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3703"><small><small> [Times:
user=0.38 sys=0.02, real=0.75 secs] <br clear="none">
The real time matches PrintGCApplicationStoppedTime.<br clear="none">
Since there are 18 gc threads, if not blocked by something,
the real time should be smaller than user time.<br clear="none">
can you check if the system is swapping or waiting on i/o?<br clear="none">
Which JVM are you using?<br clear="none">
<br clear="none">
</small></small></span>
<pre class="yiv1302500087moz-signature">Thanks,
Jenny</pre>
<div class="yiv1302500087yqt2952001786" id="yiv1302500087yqt35913"><div class="yiv1302500087moz-cite-prefix">On 10/6/2015 1:58 AM, Naman Jain wrote:<br clear="none">
</div>
<blockquote type="cite">
<div style="color:#000;background-color:#fff;font-family:HelveticaNeue, Helvetica Neue, Helvetica, Arial, Lucida Grande, Sans-Serif;font-size:13px;">
<div id="yiv1302500087yui_3_16_0_1_1444120972912_3364">Hey Everyone,</div>
<div id="yiv1302500087yui_3_16_0_1_1444120972912_3364"><br clear="none">
</div>
<div dir="ltr" id="yiv1302500087yui_3_16_0_1_1444120972912_3364">G1 GC log:</div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3521"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3523">2015-10-</span><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3525">05T14:54</span><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3527">:35.518+0000:
549629.568: [GC pause (G1 Evacuation Pause) (young)</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3529"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3531">Desired
survivor size 322961408 bytes, new threshold 15 (max 15)</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3533"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3535">- age 1:
5292232 bytes, 5292232 total</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3537"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3539">- age 2:
1201264 bytes, 6493496 total</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3541"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3543">- age 3:
377376 bytes, 6870872 total</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3545"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3547">- age 4:
440752 bytes, 7311624 total</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3549"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3551">- age 5:
201976 bytes, 7513600 total</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3553"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3555">- age 6:
77616 bytes, 7591216 total</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3557"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3559">- age 7:
28824 bytes, 7620040 total</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3561"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3563">- age 8:
55312 bytes, 7675352 total</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3565"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3567">- age 9:
55432 bytes, 7730784 total</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3569"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3571">- age 10:
14272 bytes, 7745056 total</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3573"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3575">- age 11:
16872 bytes, 7761928 total</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3577"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3579">- age 12:
18208 bytes, 7780136 total</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3581"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3583">- age 13:
11656 bytes, 7791792 total</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3585"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3587">- age 14:
15800 bytes, 7807592 total</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3589"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3591">- age 15:
33960 bytes, 7841552 total</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3593"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3595"> 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]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3597"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3599"> 549629.569:
[G1Ergonomics (CSet Construction) add young regions to CSet,
eden: 1224 regions, survivors: 4 regions, predicted young
region time: 10.73 ms]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3601"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3603"> 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]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3605"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3607">, <b id="yiv1302500087yui_3_16_0_1_1444120972912_3768">0.<span id="yiv1302500087yui_3_16_0_1_1444120972912_3750">0355102</span> secs</b>]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3609"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3611"> [Parallel
Time: 21.7 ms, GC Workers: 18]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3613"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3615"> [GC
Worker Start (ms): Min: 549629569.6, Avg: 549629569.8, Max:
549629569.9, Diff: 0.3]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3617"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3619"> [Ext
Root Scanning (ms): Min: 3.6, Avg: 4.3, Max: 12.7, Diff:
9.0, Sum: 78.1]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3621"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3623"> [Update
RS (ms): Min: 0.0, Avg: 4.1, Max: 4.7, Diff: 4.7, Sum: 74.6]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3625"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3627">
[Processed Buffers: Min: 0, Avg: 60.3, Max: 79, Diff: 79,
Sum: 1086]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3629"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3631"> [Scan RS
(ms): Min: 0.1, Avg: 2.2, Max: 2.7, Diff: 2.5, Sum: 40.4]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3633"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3635"> [Code
Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0,
Sum: 0.1]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3637"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3639"> [Object
Copy (ms): Min: 8.0, Avg: 10.2, Max: 10.5, Diff: 2.5, Sum:
183.2]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3641"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3643">
[Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2,
Sum: 2.5]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3645"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3647"> [GC
Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2,
Sum: 2.0]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3649"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3651"> [GC
Worker Total (ms): Min: 20.9, Avg: 21.2, Max: 21.4, Diff:
0.5, Sum: 381.0]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3653"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3655"> [GC
Worker End (ms): Min: 549629590.9, Avg: 549629590.9, Max:
549629591.1, Diff: 0.2]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3657"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3659"> [Code Root
Fixup: 0.3 ms]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3661"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3663"> [Code Root
Purge: 0.0 ms]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3665"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3667"> [Clear CT:
0.8 ms]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3669"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3671"> [Other:
12.6 ms]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3673"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3675"> [Choose
CSet: 0.0 ms]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3677"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3679"> [Ref
Proc: 6.2 ms]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3681"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3683"> [Ref
Enq: 0.5 ms]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3685"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3687"> [Redirty
Cards: 0.4 ms]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3689"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3691">
[Humongous Reclaim: 0.0 ms]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3693"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3695"> [Free
CSet: 2.9 ms]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3697"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3699"> [Eden:
4896.0M(4896.0M)->0.0B(4892.0M) Survivors:
16.0M->20.0M Heap: 6505.9M(8192.0M)->1611.1M(8192.0M)]</span></div>
<div class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3701"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3703"> [Times:
user=0.38 sys=0.02, real=0.75 secs] </span></div>
<div dir="ltr" id="yiv1302500087yui_3_16_0_1_1444120972912_3364">
</div>
<div class="yiv1302500087" dir="ltr" id="yiv1302500087yui_3_16_0_1_1444120972912_3705"><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3707">2015-10-</span><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3709">05T14:54</span><span class="yiv1302500087" id="yiv1302500087yui_3_16_0_1_1444120972912_3711">:36.272+0000:
549630.322: Total time for which application threads were
stopped:<b> 0.7695049</b> seconds, Stopping threads took:
0.0004596 seconds</span></div>
<div class="yiv1302500087" dir="ltr" id="yiv1302500087yui_3_16_0_1_1444120972912_3705"><span class="yiv1302500087"><br clear="none">
</span></div>
<div class="yiv1302500087" dir="ltr" id="yiv1302500087yui_3_16_0_1_1444120972912_3705">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 ?</div>
<div class="yiv1302500087" dir="ltr" id="yiv1302500087yui_3_16_0_1_1444120972912_3705">Also
why pauses other then GC pauses were included in GC logs ?</div>
<div class="yiv1302500087" dir="ltr" id="yiv1302500087yui_3_16_0_1_1444120972912_3705">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 ?</div>
<div class="yiv1302500087" dir="ltr" id="yiv1302500087yui_3_16_0_1_1444120972912_3705"><br clear="none">
</div>
<div class="yiv1302500087" dir="ltr" id="yiv1302500087yui_3_16_0_1_1444120972912_3705">Thanks</div>
<div class="yiv1302500087" dir="ltr" id="yiv1302500087yui_3_16_0_1_1444120972912_3705"><br clear="none">
</div>
<div class="yiv1302500087" dir="ltr" id="yiv1302500087yui_3_16_0_1_1444120972912_3705">-Naman</div>
<div class="yiv1302500087" dir="ltr" id="yiv1302500087yui_3_16_0_1_1444120972912_3705"><br clear="none">
</div>
</div>
<br clear="none">
<fieldset class="yiv1302500087mimeAttachmentHeader"></fieldset>
<br clear="none">
<pre>_______________________________________________
hotspot-gc-use mailing list
<a rel="nofollow" shape="rect" class="yiv1302500087moz-txt-link-abbreviated" ymailto="mailto:hotspot-gc-use@openjdk.java.net" target="_blank" href="mailto:hotspot-gc-use@openjdk.java.net">hotspot-gc-use@openjdk.java.net</a>
<a rel="nofollow" shape="rect" class="yiv1302500087moz-txt-link-freetext" target="_blank" href="http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use">http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use</a>
</pre>
</blockquote></div>
<br clear="none">
</div></div><br><br></div> </div> </div> </div></div></body></html>