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