<html>
  <head>
    <meta content="text/html; charset=windows-1252"
      http-equiv="Content-Type">
  </head>
  <body bgcolor="#FFFFFF" text="#000000">
    <br>
    Hi Thomas,<br>
    <br>
    A very late reply. I happened to find this in my inbox and have some
    comments.<br>
    <br>
    <div class="moz-cite-prefix">On 2014-08-29 14:15, Thomas Viessmann
      wrote:<br>
    </div>
    <blockquote cite="mid:54006ED6.7050006@oracle.com" type="cite">
      <meta http-equiv="content-type" content="text/html;
        charset=windows-1252">
      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>
    </blockquote>
    <br>
    <br>
    The GC starts at 48448.931 and reports that it lasts for 0.36
    seconds, so it should have ended at 48449.291. The last log line
    that states that the threads were stopped for 9 seconds is from the
    PrintGCApplicationStoppedTime flag, which logs how long the
    safepoint was. i.e. how long the Java threads where stopped.<br>
    <br>
    This means that the safepoint lasted for 9 seconds but the GC only
    lasted for 0.36 seconds. So the rest of the time must be attributed
    to stopping and starting the Java threads. The safepoint was started
    at 48444.691 (48454.034 - 9.3426141), which means that it took 4.240
    seconds (48448.931 - 48444.691) to stop all Java threads and 4.743
    seconds (9.3426141 - 4.240 - 0.36) to start them again. <br>
    <br>
    I don't have a good explanation for why it takes so long to stop and
    start the threads. Are there many Java threads in the application?
    Are there many other processes running that could cause the Java
    threads to be scheduled out?<br>
    <br>
    Thanks,<br>
    Bengt<br>
    <br>
    <blockquote cite="mid:54006ED6.7050006@oracle.com" type="cite"> <br>
      <br>
      <br>
      Thanks and Regards<br>
      <br>
      Thomas <br>
      <br>
      <div class="moz-signature">-- <br>
        <a moz-do-not-send="true" href="http://www.oracle.com"
          target="_blank"><img style="border: 0px solid ; width: 114px;
            height: 26px;" src="cid:part1.08090100.00010306@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 moz-do-not-send="true" href="tel:+49814302496">+498914302496</a>
          | Mobile: <a moz-do-not-send="true" 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 moz-do-not-send="true"
          href="http://www.oracle.com/commitment" target="_blank"><img
            style="border: 0px solid ; width: 44px; height: 28px;"
            src="cid:part5.02000801.01000006@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>
    </blockquote>
    <br>
  </body>
</html>