<html>
<head>
<meta http-equiv="content-type" content="text/html; charset=ISO-8859-1">
</head>
<body bgcolor="#FFFFFF" text="#000000">
Hi all,<br>
<br>
<br>
I suspect a bug in G1 logging. Before I file a (possibly incorrect)
bug I would like to ask here.<br>
Is my understanding correct that the stw evacuation phase starts at
<tt><font color="#ff0000"><b>48448.931</b></font></tt> and ends at <tt><b><font
color="#ff0000">48454</font></b><b><font color="#ff0000">.034</font></b></tt>
?<br>
This would mean a stop time of 5.103 s, which is clearly a mismatch
to the reported <b><small><font color="#ff0000">9.3426141</font></small></b>
s<br>
If the stw phase in fact started at a later time e.g. at <tt><b><font
color="#ff0000">48449.288 </font></b></tt>then the stop pause
would have been even shorter.<br>
<br>
In addition I do not understand how all the relatively short
evacuation phases sum up to several seconds.<br>
If I add all the MAX values <b><font color="#00cccc"><tt>69.1 + </tt><tt>22.2</tt>
+ <tt>45</tt><tt> + 150.8 + </tt><tt>0.1</tt> + <tt>155.1</tt>
+ <tt>0.9 + </tt><tt>0.5</tt></font></b><small> <b><font
color="#00cccc">= 443.7</font></b><b><font color="#00cccc">ms</font></b></small><br>
<br>
<br>
<br>
<tt><br>
</tt><tt>48443.380: Total time for which application threads were
stopped: 0.0084701 seconds</tt><tt><br>
</tt><tt><font color="#ff0000"><b>48448.931</b></font>: [GC pause
(mixed) 48448.931: [G1Ergonomics (CSet Construction) start
choosing CSet, _pending_cards: 89458, predicted base time: 73.58
ms, remaining time: 176.42 ms, target pause time: 250.00 ms]</tt><tt><br>
</tt><tt> 48448.931: [G1Ergonomics (CSet Construction) add young
regions to CSet, eden: 33 regions, survivors: 5 regions, predicted
young region time: 35.73 ms]</tt><tt><br>
</tt><tt> 48448.933: [G1Ergonomics (CSet Construction) finish adding
old regions to CSet, reason: reclaimable percentage not over
threshold, old: 19 regions, max: 77 regions, reclaimable:
2570649712 bytes (9.98 %), threshold: 10.00 %]</tt><tt><br>
</tt><tt> 48448.933: [G1Ergonomics (CSet Construction) added
expensive regions to CSet, reason: old CSet region num not reached
min, old: 19 regions, expensive: 7 regions, min: 26 regions,
remaining time: 0.00 ms]</tt><tt><br>
</tt><tt> 48448.933: [G1Ergonomics (CSet Construction) finish
choosing CSet, eden: 33 regions, survivors: 5 regions, old: 19
regions, predicted pause time: 340.58 ms, target pause time:
250.00 ms]</tt><tt><br>
</tt><tt>48449.252: [SoftReference, 962 refs, 0.0064679
secs]48449.259: [WeakReference, 7411 refs, 0.0027722
secs]48449.261: [FinalReference, 272 refs, 0.0022754
secs]48449.264: [PhantomReference, 6 refs, 0.0024348
secs]48449.266: [JNI Weak Reference, 0.0000337 secs] 48449.288:
[G1Ergonomics (Concurrent Cycles) do not request concurrent cycle
initiation, reason: still doing mixed collections, occupancy:
14898167808 bytes, allocation request: 0 bytes, threshold:
11596411665 bytes (45.00 %), source: end of GC]</tt><tt><br>
</tt><tt> <b><font color="#ff0000">48449.288</font></b>:
[G1Ergonomics (Mixed GCs) do not continue mixed GCs, reason:
reclaimable percentage not over threshold, candidate old regions:
156 regions, reclaimable: 2570649712 bytes (9.98 %), threshold:
10.00 %]</tt><tt><br>
</tt><tt>, 0.3573636 secs]</tt><tt><br>
</tt><tt> [Parallel Time: 314.9 ms, GC Workers: 40]</tt><tt><br>
</tt><tt> [GC Worker Start (ms): Min: 48448933.6, Avg:
48448934.2, Max: 48448934.7, Diff: 1.1]</tt><tt><br>
</tt><tt> [Ext Root Scanning (ms): Min: 15.1, Avg: 17.7, Max: <b><font
color="#00cccc">69.1</font></b>, Diff: 54.0, Sum: 708.0]</tt><tt><br>
</tt><tt> [Update RS (ms): Min: 0.0, Avg: 14.5, Max: <b><font
color="#00cccc">22.2</font></b>, Diff: 22.2, Sum: 580.3]</tt><tt><br>
</tt><tt> [Processed Buffers: Min: 0, Avg: 22.0, Max: <b><font
color="#00cccc">45</font></b>, Diff: 45, Sum: 879]</tt><tt><br>
</tt><tt> [Scan RS (ms): Min: 88.7, Avg: 142.6, Max: <b><font
color="#00cccc">150.8</font></b>, Diff: 62.1, Sum: 5705.2]</tt><tt><br>
</tt><tt> [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: <b><font
color="#00cccc">0.1</font></b>, Diff: 0.1, Sum: 0.1]</tt><tt><br>
</tt><tt> [Object Copy (ms): Min: 131.4, Avg: 138.2, Max: <b><font
color="#00cccc">155.1</font></b>, Diff: 23.8, Sum: 5526.6]</tt><tt><br>
</tt><tt> [Termination (ms): Min: 0.0, Avg: 0.7, Max: <b><font
color="#00cccc">0.9</font></b>, Diff: 0.9, Sum: 27.2]</tt><tt><br>
</tt><tt> [GC Worker Other (ms): Min: 0.0, Avg: 0.3, Max: <b><font
color="#00cccc">0.5</font></b>, Diff: 0.5, Sum: 10.0]</tt><tt><br>
</tt><tt> [GC Worker Total (ms): Min: 313.2, Avg: 313.9, Max: <b><font
color="#00cccc">314.7</font></b>, Diff: 1.5, Sum: 12557.5]</tt><tt><br>
</tt><tt> [GC Worker End (ms): Min: 48449247.9, Avg:
48449248.1, Max: 48449248.4, Diff: 0.5]</tt><tt><br>
</tt><tt> [Code Root Fixup: 2.2 ms]</tt><tt><br>
</tt><tt> [Code Root Migration: 0.2 ms]</tt><tt><br>
</tt><tt> [Clear CT: 2.0 ms]</tt><tt><br>
</tt><tt> [Other: 38.2 ms]</tt><tt><br>
</tt><tt> [Choose CSet: 1.7 ms]</tt><tt><br>
</tt><tt> [Ref Proc: 15.6 ms]</tt><tt><br>
</tt><tt> [Ref Enq: 1.2 ms]</tt><tt><br>
</tt><tt> [Free CSet: 2.4 ms]</tt><tt><br>
</tt><tt> [Eden: 1056.0M(1056.0M)->0.0B(1088.0M) Survivors:
160.0M->128.0M Heap: 14.5G(24.0G)->13.9G(24.0G)]</tt><tt><br>
</tt><tt> [Times: user=12.45 sys=0.03, real=0.36 secs] </tt><tt><br>
</tt><tt><b><font color="#ff0000">48454</font></b><b><font
color="#ff0000">.034</font></b>: Total time for which
application threads were stopped: <b><font color="#ff0000">9.3426141</font></b>
seconds</tt><tt><br>
</tt><br>
For completeness; here are the cmd line options:<br>
<br>
<br>
/usr/jdk/instances/jdk1.7.0/bin/sparcv9/java -Xms24g -Xmx24g
-server -XX:StringTableSize=27001 -XX:PermSize=512m
-XX:MaxPermSize=512m -Xss512k <br>
-XX:+UseG1GC -XX:SoftRefLRUPolicyMSPerMB=500 -XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-Xloggc:/var/cacao/instances/oem-ec/logs/gc.log
-XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10
-XX:GCLogFileSize=10m -XX:+PrintGCApplicationStoppedTime
-XX:MaxGCPauseMillis=250-XX:InitiatingHeapOccupancyPercent=45
-XX:+ParallelRefProcEnabled -XX:ParallelGCThreads=40
-XX:+PrintAdaptiveSizePolicy -XX:+PrintSafepointStatistics
-XX:+PrintReferenceGC -XX:G1HeapRegionSize=32m
-XX:HeapBaseMinAddress=2G <br>
<br>
<br>
<br>
Thanks and Regards<br>
<br>
Thomas <br>
<br>
<div class="moz-signature">-- <br>
<a href="http://www.oracle.com" target="_blank"><img
style="border: 0px solid ; width: 114px; height: 26px;"
src="cid:part1.05000301.06090701@oracle.com" alt="Oracle"></a><br>
<font color="#666666" face="Verdana, Arial, Helvetica, sans-serif"
size="2">THOMAS VIESSMANN | Senior Principal Technical Support
Engineer - Java<br>
Phone: <a href="tel:+49814302496">+498914302496</a> | Mobile: <a
href="tel:+491743005467">+491743005467</a> <br>
<font color="#ff0000">Oracle</font> Customer Technical Support -
Java<br>
<br>
ORACLE Deutschland B.V. & Co. KG | Riesstr.25 | D-80992
Muenchen </font><br>
<br>
<font color="#666666" face="Verdana, Arial, Helvetica, sans-serif"
size="1">ORACLE Deutschland B.V. & Co. KG<br>
Hauptverwaltung: Riesstr. 25, D-80992 Muenchen<br>
Registergericht: Amtsgericht Muenchen, HRA 95603<br>
Geschäftsführere: Juergen Kunz<br>
<br>
Komplementärin: ORACLE Deutschland Verwaltung B.V.<br>
Hertogswetering 163/167, 3543 AS Utrecht, Niederlande<br>
Handelsregister der Handelskammer Midden-Niederlande, Nr.
30143697<br>
Geschäftsführer: Alexander van der Ven, Astrid Kepper, Val Maher<br>
</font>
<br>
<hr>
<hr>
<a href="http://www.oracle.com/commitment" target="_blank"><img
style="border: 0px solid ; width: 44px; height: 28px;"
src="cid:part5.08030205.02080707@oracle.com" alt="Green
Oracle" align="middle"></a>
<font color="#4b7d42" face="Verdana, Arial, Helvetica, sans-serif"
size="1">Oracle is committed to developing practices and
products that help protect the environment</font>
<!-- This signature was generated by the MyDesktop Oracle Business Signature utility version 3.8.6 -->
</div>
</body>
</html>