44   static String output;

    44     static String output;

    45   static final String doubleRegex = "[0-9]+[.,][0-9]+";

    45     static final String doubleRegex = "[0-9]+[.,][0-9]+";

    46   static final String referenceProcessing = "Reference Processing";

    46     static final String referenceProcessing = "Reference Processing";

    47   static final String softReference = "SoftReference";

    47     static final String softReference = "SoftReference";

    48   static final String weakReference = "WeakReference";

    48     static final String weakReference = "WeakReference";

    49   static final String finalReference = "FinalReference";

    49     static final String finalReference = "FinalReference";

    50   static final String phantomReference = "PhantomReference";

    50     static final String phantomReference = "PhantomReference";

    51   static final String phase1 = "Phase1";

    51 

    52   static final String phase2 = "Phase2";

    52     static final String phaseReconsiderSoftReferences = "Reconsider SoftReferences";

    53   static final String phase3 = "Phase3";

    53     static final String phaseNotifySoftWeakReferences = "Notify Soft/WeakReferences";

    54   static final String gcLogTimeRegex = ".* GC\\([0-9]+\\) ";

    54     static final String phaseNotifyKeepAliveFinalizer = "Notify and keep alive finalizable";

    55 

    55     static final String phaseNotifyPhantomReferences  = "Notify PhantomReferences";

    56   public static void main(String[] args) throws Exception {

    56 

    57     test(true);

    57     static final String phase1 = "Phase1";

    58     test(false);

    58     static final String phase2 = "Phase2";

    59   }

    59     static final String phase3 = "Phase3";

    60 

    60     static final String gcLogTimeRegex = ".* GC\\([0-9]+\\) ";

    61   static String indent(int count) {

    61 

    62     return " {" + count + "}";

    62     public static void main(String[] args) throws Exception {

    63   }

    63         testPhases(true);

    64 

    64         testPhases(false);

    65   public static void test(boolean parallelRefProcEnabled) throws Exception {

    65         testRefs();

    66     ProcessBuilder pb_enabled = ProcessTools.createJavaProcessBuilder("-Xlog:gc+phases+ref=debug",

    66     }

    67                                                                       "-XX:+UseG1GC",

    67 

    68                                                                       "-Xmx32M",

    68     static String indent(int count) {

    69                                                                       // Explicit thread setting is required to avoid using only 1 thread

    69         return " {" + count + "}";

    70                                                                       "-XX:" + (parallelRefProcEnabled ? "+" : "-") + "ParallelRefProcEnabled",

    70     }

    71                                                                       "-XX:ParallelGCThreads=2",

    71 

    72                                                                       GCTest.class.getName());

    72     public static void testRefs() throws Exception {

    73     OutputAnalyzer output = new OutputAnalyzer(pb_enabled.start());

    73         ProcessBuilder pb_enabled = ProcessTools.createJavaProcessBuilder("-Xlog:gc+ref+phases=debug",

    74 

    74                                                                           "-XX:+UseG1GC",

    75     checkLogFormat(output, parallelRefProcEnabled);

    75                                                                           "-Xmx32M",

    76     checkLogValue(output);

    76                                                                           GCTest.class.getName());

    77 

    77         OutputAnalyzer output = new OutputAnalyzer(pb_enabled.start());

    78     output.shouldHaveExitValue(0);

    78 

    79   }

    79         checkRefsLogFormat(output);

    80 

    80 

    81   // Find the first Reference Processing log and check its format.

    81         output.shouldHaveExitValue(0);

    82   public static void checkLogFormat(OutputAnalyzer output, boolean parallelRefProcEnabled) {

    82     }

    83     String countRegex = "[0-9]+";

    83 

    84     String timeRegex = doubleRegex + "ms";

    84     private static String refRegex(String reftype) {

    85     String totalRegex = gcLogTimeRegex + indent(4) + referenceProcessing + ": " + timeRegex + "\n";

    85         String countRegex = "[0-9]+";

    86     String balanceRegex = parallelRefProcEnabled ? gcLogTimeRegex + indent(8) + "Balance queues: " + timeRegex + "\n" : "";

    86         return gcLogTimeRegex + indent(6) + reftype + ":\n" +

    87     String softRefRegex = gcLogTimeRegex + indent(6) + softReference + ": " + timeRegex + "\n";

    87                gcLogTimeRegex + indent(8) + "Discovered: " + countRegex + "\n" +

    88     String weakRefRegex = gcLogTimeRegex + indent(6) + weakReference + ": " + timeRegex + "\n";

    88                gcLogTimeRegex + indent(8) + "Cleared: " + countRegex + "\n";

    89     String finalRefRegex = gcLogTimeRegex + indent(6) + finalReference + ": " + timeRegex + "\n";

    89     }

    90     String phantomRefRegex = gcLogTimeRegex + indent(6) + phantomReference + ": " + timeRegex + "\n";

    90 

    91     String refDetailRegex = gcLogTimeRegex + indent(8) + phase2 + ": " + timeRegex + "\n" +

    91     private static void checkRefsLogFormat(OutputAnalyzer output) {

    92                             gcLogTimeRegex + indent(8) + phase3 + ": " + timeRegex + "\n" +

    92         output.shouldMatch(refRegex("SoftReference") +

    93                             gcLogTimeRegex + indent(8) + "Discovered: " + countRegex + "\n" +

    93                            refRegex("WeakReference") +

    94                             gcLogTimeRegex + indent(8) + "Cleared: " + countRegex + "\n";

    94                            refRegex("FinalReference") +

    95     String softRefDetailRegex = gcLogTimeRegex + indent(8) + phase1 + ": " + timeRegex + "\n" + refDetailRegex;

    95                            refRegex("PhantomReference"));

    96 

    96     }

    97     output.shouldMatch(/* Total Reference processing time */

    97 

    98                        totalRegex +

    98     public static void testPhases(boolean parallelRefProcEnabled) throws Exception {

    99                        /* SoftReference processing */

    99         ProcessBuilder pb_enabled = ProcessTools.createJavaProcessBuilder("-Xlog:gc+phases+ref=debug",

   100                        softRefRegex + balanceRegex + softRefDetailRegex +

   100                                                                           "-XX:+UseG1GC",

   101                        /* WeakReference processing */

   101                                                                           "-Xmx32M",

   102                        weakRefRegex + balanceRegex + refDetailRegex +

   102                                                                           "-XX:" + (parallelRefProcEnabled ? "+" : "-") + "ParallelRefProcEnabled",

   103                        /* FinalReference processing */

   103                                                                           "-XX:-UseDynamicNumberOfGCThreads",

   104                        finalRefRegex + balanceRegex + refDetailRegex +

   104                                                                           "-XX:ParallelGCThreads=2",

   105                        /* PhantomReference processing */

   105                                                                           GCTest.class.getName());

   106                        phantomRefRegex + balanceRegex + refDetailRegex

   106         OutputAnalyzer output = new OutputAnalyzer(pb_enabled.start());

   107                        );

   107 

   108   }

   108         checkLogFormat(output, parallelRefProcEnabled);

   109 

   109         checkLogValue(output);

   110   // After getting time value, update 'output' for next use.

   110 

   111   public static BigDecimal getTimeValue(String name, int indentCount) {

   111         output.shouldHaveExitValue(0);

   112     // Pattern of 'name', 'value' and some extra strings.

   112     }

   113     String patternString = gcLogTimeRegex + indent(indentCount) + name + ": " + "(" + doubleRegex + ")";

   113 

   114     Matcher m = Pattern.compile(patternString).matcher(output);

   114     private static String phaseRegex(String phaseName) {

   115      if (!m.find()) {

   115         final String timeRegex = doubleRegex + "ms";

   116       throw new RuntimeException("Could not find time log for " + patternString);

   116         return indent(6) + phaseName + ": " + timeRegex + "\n";

   117      }

   117     }

   118 

   118 

   119     String match = m.group();

   119     private static String subphaseRegex(String subphaseName, boolean parallelRefProcEnabled) {

   120     String value = m.group(1);

   120         final String timeRegex = "\\s+" + doubleRegex;

   121 

   121         if (parallelRefProcEnabled) {

   122     double result = Double.parseDouble(value);

   122             final String timeInParRegex = timeRegex +",\\s";

   123 

   123             return gcLogTimeRegex + indent(8) + subphaseName +

   124     int index = output.indexOf(match);

   124                    " \\(ms\\):\\s+Min: " + timeInParRegex + "Avg: " + timeInParRegex + "Max: " + timeInParRegex + "Diff: " + timeInParRegex + "Sum: " + timeInParRegex +

   125     if (index != -1) {

   125                    "Workers: [0-9]+" + "\n";

   126       output = output.substring(index, output.length());

   126         } else {

   127     }

   127             return gcLogTimeRegex + indent(8) + subphaseName + ":" + timeRegex + "ms\n";

   128 

   128         }

   129     // Convert to BigDecimal to control the precision of floating point arithmetic.

   129     }

   130     return BigDecimal.valueOf(result);

   130 

   131   }

   131     // Find the first Reference Processing log and check its format.

   132 

   132     private static void checkLogFormat(OutputAnalyzer output, boolean parallelRefProcEnabled) {

   133   // Reference log is printing 1 decimal place of elapsed time.

   133         String countRegex = "[0-9]+";

   134   // So sum of each sub-phases could be slightly larger than the enclosing phase in some cases.

   134         String timeRegex = doubleRegex + "ms";

   135   // e.g. If there are 3 sub-phases:

   135 

   136   //      Actual value:  SoftReference(5.55) = phase1(1.85) + phase2(1.85) + phase3(1.85)

   136         /* Total Reference processing time */

   137   //      Log value:     SoftReference(5.6) = phase1(1.9) + phase2(1.9) + phase3(1.9)

   137         String totalRegex = gcLogTimeRegex + indent(4) + referenceProcessing + ": " + timeRegex + "\n";

   138   //      When checked:  5.6 < 5.7 (sum of phase1~3)

   138 

   139   // Because of this we need method to verify that our measurements and calculations are valid.

   139         String balanceRegex = parallelRefProcEnabled ? gcLogTimeRegex + indent(8) + "Balance queues: " + timeRegex + "\n" : "";

   140   public static boolean greaterThanOrApproximatelyEqual(BigDecimal phaseTime, BigDecimal sumOfSubPhasesTime, BigDecimal tolerance) {

   140 

   141     if (phaseTime.compareTo(sumOfSubPhasesTime) >= 0) {

   141         final boolean p = parallelRefProcEnabled;

   142       // phaseTime is greater than or equal.

   142 

   143       return true;

   143         String phase1Regex = gcLogTimeRegex + phaseRegex(phaseReconsiderSoftReferences) + balanceRegex + subphaseRegex("SoftRef", p);

   144     }

   144         String phase2Regex = gcLogTimeRegex + phaseRegex(phaseNotifySoftWeakReferences) +

   145 

   145                              balanceRegex +

   146     BigDecimal diff = sumOfSubPhasesTime.subtract(phaseTime);

   146                              subphaseRegex("SoftRef", p) +

   147     if (diff.compareTo(tolerance) <= 0) {

   147                              subphaseRegex("WeakRef", p) +

   148       // Difference is within tolerance, so approximately equal.

   148                              subphaseRegex("FinalRef", p) +

   149       return true;

   149                              subphaseRegex("Total", p);

   150     }

   150         String phase3Regex = gcLogTimeRegex + phaseRegex(phaseNotifyKeepAliveFinalizer) + balanceRegex + subphaseRegex("FinalRef", p);

   151 

   151         String phase4Regex = gcLogTimeRegex + phaseRegex(phaseNotifyPhantomReferences) + balanceRegex + subphaseRegex("PhantomRef", p);

   152     // sumOfSubPhasesTime is greater than phaseTime and not within tolerance.

   152 

   153     return false;

   153         output.shouldMatch(totalRegex +

   154   }

   154                            phase1Regex +

   155 

   155                            phase2Regex +

   156   public static BigDecimal checkPhaseTime(String refType) {

   156                            phase3Regex +

   157     BigDecimal phaseTime = getTimeValue(refType, 2);

   157                            phase4Regex);

   158     BigDecimal sumOfSubPhasesTime = BigDecimal.valueOf(0.0);

   158     }

   159 

   159 

   160     if (softReference.equals(refType)) {

   160     // After getting time value, update 'output' for next use.

   161       sumOfSubPhasesTime = sumOfSubPhasesTime.add(getTimeValue(phase1, 4));

   161     private static BigDecimal getTimeValue(String name, int indentCount) {

   162     }

   162         // Pattern of 'name', 'value' and some extra strings.

   163     sumOfSubPhasesTime = sumOfSubPhasesTime.add(getTimeValue(phase2, 4));

   163         String patternString = gcLogTimeRegex + indent(indentCount) + name + ": " + "(" + doubleRegex + ")";

   164     sumOfSubPhasesTime = sumOfSubPhasesTime.add(getTimeValue(phase3, 4));

   164         Matcher m = Pattern.compile(patternString).matcher(output);

   165 

   165         if (!m.find()) {

   166     // If there are 3 sub-phases, we should allow 0.1 tolerance.

   166             throw new RuntimeException("Could not find time log for " + patternString);

   167     final BigDecimal toleranceFor3SubPhases = BigDecimal.valueOf(0.1);

   167         }

   168     if (!greaterThanOrApproximatelyEqual(phaseTime, sumOfSubPhasesTime, toleranceFor3SubPhases)) {

   168 

   169       throw new RuntimeException(refType +" time(" + phaseTime +

   169         String match = m.group();

   170                                  "ms) is less than the sum(" + sumOfSubPhasesTime + "ms) of each phases");

   170         String value = m.group(1);

   171     }

   171 

   172 

   172         double result = Double.parseDouble(value);

   173     return phaseTime;

   173 

   174   }

   174         int index = output.indexOf(match);

   175 

   175         if (index != -1) {

   176   // Find the first concurrent Reference Processing log and compare phase time vs. sum of sub-phases.

   176             output = output.substring(index, output.length());

   177   public static void checkLogValue(OutputAnalyzer out) {

   177         }

   178     output = out.getStdout();

   178 

   179 

   179         // Convert to BigDecimal to control the precision of floating point arithmetic.

   180     String patternString = gcLogTimeRegex + indent(0) +

   180         return BigDecimal.valueOf(result);

   181                            referenceProcessing + ": " + "[0-9]+[.,][0-9]+";

   181    }

   182     Matcher m = Pattern.compile(patternString).matcher(output);

   182 

   183     if (m.find()) {

   183     // Reference log is printing 1 decimal place of elapsed time.

   184         int start = m.start();

   184     // So sum of each sub-phases could be slightly larger than the enclosing phase in some cases.

   185         int end = output.length();

   185     // Because of this we need method to verify that our measurements and calculations are valid.

   186         // If there's another concurrent Reference Processing log, ignore it.

   186     private static boolean greaterThanOrApproximatelyEqual(BigDecimal phaseTime, BigDecimal sumOfSubPhasesTime, BigDecimal tolerance) {

   187         if (phaseTime.compareTo(sumOfSubPhasesTime) >= 0) {

   188             // phaseTime is greater than or equal.

   189             return true;

   190         }

   191 

   192         BigDecimal diff = sumOfSubPhasesTime.subtract(phaseTime);

   193         if (diff.compareTo(tolerance) <= 0) {

   194             // Difference is within tolerance, so approximately equal.

   195             return true;

   196         }

   197 

   198         // sumOfSubPhasesTime is greater than phaseTime and not within tolerance.

   199         return false;

   200     }

   201 

   202     // Find the first concurrent Reference Processing log and compare phase time vs. sum of sub-phases.

   203     public static void checkLogValue(OutputAnalyzer out) {

   204         output = out.getStdout();

   205 

   206         String patternString = gcLogTimeRegex + indent(0) +

   207                                referenceProcessing + ": " + "[0-9]+[.,][0-9]+";

   208         Matcher m = Pattern.compile(patternString).matcher(output);

   188             end = m.start();

   210             int start = m.start();

   189         }

   211             int end = output.length();

   190         if (start != -1) {

   212             // If there's another concurrent Reference Processing log, ignore it.

   191             output = output.substring(start, end);

   213             if (m.find()) {

   192             checkTrimmedLogValue();

   214                 end = m.start();

   193         }

   215             }

   194      }

   216             if (start != -1) {

   195   }

   217                 output = output.substring(start, end);

   196 

   218                 checkTrimmedLogValue();

   197   public static void checkTrimmedLogValue() {

   219             }

   198     BigDecimal refProcTime = getTimeValue(referenceProcessing, 0);

   220         }

   199 

   221     }

   200     BigDecimal sumOfSubPhasesTime = checkPhaseTime(softReference);

   222 

   201     sumOfSubPhasesTime = sumOfSubPhasesTime.add(checkPhaseTime(weakReference));

   223     private static void checkTrimmedLogValue() {

   202     sumOfSubPhasesTime = sumOfSubPhasesTime.add(checkPhaseTime(finalReference));

   224         BigDecimal refProcTime = getTimeValue(referenceProcessing, 0);

   203     sumOfSubPhasesTime = sumOfSubPhasesTime.add(checkPhaseTime(phantomReference));

   225 

   204 

   226         BigDecimal sumOfSubPhasesTime = getTimeValue(phaseReconsiderSoftReferences, 2);

   205     // If there are 4 sub-phases, we should allow 0.2 tolerance.

   227         sumOfSubPhasesTime = sumOfSubPhasesTime.add(getTimeValue(phaseNotifySoftWeakReferences, 2));

   206     final BigDecimal toleranceFor4SubPhases = BigDecimal.valueOf(0.2);

   228         sumOfSubPhasesTime = sumOfSubPhasesTime.add(getTimeValue(phaseNotifyKeepAliveFinalizer, 2));

   207     if (!greaterThanOrApproximatelyEqual(refProcTime, sumOfSubPhasesTime, toleranceFor4SubPhases)) {

   229         sumOfSubPhasesTime = sumOfSubPhasesTime.add(getTimeValue(phaseNotifyPhantomReferences, 2));

   208       throw new RuntimeException("Reference Processing time(" + refProcTime + "ms) is less than the sum("

   230 

   209                                  + sumOfSubPhasesTime + "ms) of each phases");

   231         // If there are 4 phases, we should allow 0.2 tolerance.

   210     }

   232         final BigDecimal toleranceFor4SubPhases = BigDecimal.valueOf(0.2);

   211   }

   233         if (!greaterThanOrApproximatelyEqual(refProcTime, sumOfSubPhasesTime, toleranceFor4SubPhases)) {

   212 

   234             throw new RuntimeException("Reference Processing time(" + refProcTime + "ms) is less than the sum("

   213   static class GCTest {

   235                                        + sumOfSubPhasesTime + "ms) of each phases");

   214     static final int SIZE = 512 * 1024;

   236         }

   215     static Object[] dummy = new Object[SIZE];

   237     }

   216 

   238 

   217     public static void main(String [] args) {

   239     static class GCTest {

   218       for (int i = 0; i < SIZE; i++) {

   240         static final int SIZE = 512 * 1024;

   219         dummy[i] = new SoftReference<>(new Object());

   241         static Object[] dummy = new Object[SIZE];

   220       }

   242 

   221     }

   243         public static void main(String [] args) {

   222   }

   244              for (int i = 0; i < SIZE; i++) {

   245                   dummy[i] = new SoftReference<>(new Object());

   246              }

   247         }

   248     }