<html>
  <head>
    <meta content="text/html; charset=utf-8" http-equiv="Content-Type">
  </head>
  <body bgcolor="#FFFFFF" text="#000000">
    <br>
    <div class="moz-cite-prefix">On 2014-10-02 15:07, charlie hunt
      wrote:<br>
    </div>
    <blockquote
      cite="mid:B67B350F-F1ED-4A99-A2B5-65CF57121434@oracle.com"
      type="cite">
      <meta http-equiv="content-type" content="text/html; charset=utf-8">
      <div>Hi Thomas,</div>
      <div><br>
      </div>
      <div>Don't mean to jump in the middle of your discussion with
        Bengt ...</div>
      <div><br>
      </div>
      <div>Since this is M5, have you tried setting the FX Solaris CPU
        scheduler, (based on the hypothesis this may be thread
        scheduling related)?</div>
    </blockquote>
    <br>
    Good point, Charlie. My guess is that there is some kind of
    scheduling issue. 2200 threads are quite a few threads to start and
    stop...<br>
    <br>
    Thomas, have you tried with ParallelGC to see if you happen to get
    the same issue there. If it is a scheduling issue for safepoints I
    don't think it should be GC dependent.<br>
    <br>
    Bengt<br>
    <br>
    <blockquote
      cite="mid:B67B350F-F1ED-4A99-A2B5-65CF57121434@oracle.com"
      type="cite">
      <div><br>
      </div>
      <div>hths,</div>
      <div><br>
      </div>
      <div>Charlie</div>
      <div><br>
      </div>
      <div><br>
      </div>
      <div><br>
        Sent from my iPhone</div>
      <div><br>
        On Oct 2, 2014, at 5:35 AM, Thomas Viessmann <<a
          moz-do-not-send="true"
          href="mailto:thomas.viessmann@oracle.com">thomas.viessmann@oracle.com</a>>
        wrote:<br>
        <br>
      </div>
      <blockquote type="cite">
        <div>
          <meta content="text/html; charset=utf-8"
            http-equiv="Content-Type">
          <tt>Hi Bengt,</tt><tt><br>
          </tt><tt><br>
          </tt><tt>Better late than never </tt><tt><span
              class="moz-smiley-s1"><span> :-) </span></span></tt><tt>.</tt><tt><br>
          </tt><tt>There are 2200 threads, about 10% are runnable.</tt><tt><br>
          </tt><tt>The application is the only one running on this M5.</tt><tt><br>
          </tt><tt><br>
          </tt><tt>We observe this effect quite often with G1.
            Relatively short</tt><tt><br>
          </tt><tt>GC times and long application thread stop times.</tt><tt><br>
          </tt><tt>Interestingly I</tt><tt>'ve never seen this with CMS.
            But</tt><tt><br>
          </tt><tt>CMS is not an option here due to fragmentation.</tt><tt><br>
          </tt><tt><br>
          </tt><tt>Thanks and Regards</tt><tt><br>
          </tt><tt><br>
          </tt><tt>Thomas </tt><tt><br>
          </tt><br>
          <br>
          <br>
          <br>
          <br>
          <br>
          <br>
          <br>
          <div class="moz-cite-prefix">On 10/02/14 11:15, Bengt Rutisson
            wrote:<br>
          </div>
          <blockquote cite="mid:542D17BE.9050104@oracle.com" type="cite">
            <meta content="text/html; charset=utf-8"
              http-equiv="Content-Type">
            <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=utf-8">
              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"><mime-attachment.gif></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"><mime-attachment.gif></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>
          </blockquote>
          <br>
          <div class="moz-signature">-- <br>
            <a moz-do-not-send="true" href="http://www.oracle.com"
              target="_blank"><oracle_sig_logo.gif></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"><green-for-email-sig_0.gif></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>
        </div>
      </blockquote>
    </blockquote>
    <br>
  </body>
</html>